Read legend JSON file from file system

[lucadelu]

Is your feature request related to a problem? Please describe

The problem is that the getLegend request to get the icons for the legend is really time consuming (depending on layers number and style complexity it can arrive to take more than 30 seconds) and it is blocking the entire website

Describe the solution you'd like

Create the JSON file within the plugin and save the file with the .qgs and .cfg file and read from it

Describe alternatives you've considered

Put a "loader" that not permit to use the client and set a sentence like "we are loading layer and styles for a better experience" until the getlegend request

[mind84]

hi @lucadelu,

one thing you can do to speed up loading is to store the PHP session data cache in a database (e.g. Redis or other). By default PHP stores the session in a file and each request can access this file one at a time, making the application "synchronous". This means that each request is not processed in parallel, but serially since each of them must access the file where the session data is stored. Storing the session cache in a DB allows to process the request in parallel.

Of course this will NOT reduce the time consumption of each request but the application loads asynchronously and became "usable". In particular, getLegendGraphic is unfortunately directly proportional to the number of layers and, at the time of writing, there is nothing you can do about it.

[lucadelu]

hi @lucadelu,

hi @mind84,

one thing you can do to speed up loading is to store the PHP session data cache in a database (e.g. Redis or other). By default PHP stores the session in a file and each request can access this file one at a time, making the application "synchronous". This means that each request is not processed in parallel, but serially since each of them must access the file where the session data is stored. Storing the session cache in a DB allows to process the request in parallel.

ok, how can I set it, just changing the php.ini ?

Of course this will NOT reduce the time consumption of each request but the application loads asynchronously and became "usable". In particular, getLegendGraphic is unfortunately directly proportional to the number of layers and, at the time of writing, there is nothing you can do about it.

ok, so why not read it from a file? It is a small file less than 1MB for hundred layer but it takes time

[gioman]

ok, so why not read it from a file? It is a small file less than 1MB for hundred layer but it takes time

This seems a reasonable request/solution for a problem that affects the platform since it moved to use the legend in JSON format rather than png as it did before, if I understand well the problem. I guess that the really issue is the longer time that QGIS Server takes to generate the JSON, still the suggestion seems a good solution to "solve" the problem from the LMWC side of things. Is there any room for discussion about how LMWC could help making it happen?

[gianvav]

From version 3.6 to 3.7 lizmap, the application's ability to satisfy the needs of public administrations that need to overlap a lot of structured technical information has disappeared.
The request for getLegendGraphic is directly proportional to the number of layers but also to their style, increasing in case of categorized styles rather than single symbol style.
It is therefore not only a problem linked to the quantity of layers, but also of communication.
For a project intended for medium-sized technical users (professionals, engineers, architects), the response time of getLegendGraphic varies from 40 seconds up to a minute, causing frequent timeouts and an unpleasant experience.

The time could be reset if the legend was created together with the project and the conf file.

[Gustry]

The legend depends on different things : user rights(group visibility for a layer) for the current logged user, scale visibility for rule based renderer etc
I'm not sure, but also the state of collapsed legend a well will change the response time (it says in the plugin that it decrease performance if legend image is displayed at startup, I can check that)

It would be interesting to first compare the GetLegendGraphic in image format, in JSON format (both without Lizmap server plugin), image and JSON format again but with the plugin

A server cache would make more sense than generating static files IMHO, so it's automatic,

[gioman]

A server cache would make more sense than generating static files IMHO, so it's automatic,

@Gustry Yeah, I understand that would be the ideal solution, or may be even better would be to make QGIS Server quicker. Still I think here there is really an issue for many. Maybe the plugin solution could help mitigate it on the short term; as the plugin now talks with the server, maybe it could be made smart enough to generate all the necessary legends depending on rights for groups, etc. (just rumbling here). Either way... I'm available to support any type of effort that would make possible to move on from 3.6.

[lucadelu]

The legend depends on different things : user rights(group visibility for a layer) for the current logged user, scale visibility for rule based renderer etc I'm not sure, but also the state of collapsed legend a well will change the response time (it says in the plugin that it decrease performance if legend image is displayed at startup, I can check that)

yes this is true, however you could add all layer to the json file and filter it later on the client

It would be interesting to first compare the GetLegendGraphic in image format, in JSON format (both without Lizmap server plugin), image and JSON format again but with the plugin

I tested the single request without JSON format is really faster, the mail problem I think is the base64 conversion, it is cool but take a lot of time to be done

A server cache would make more sense than generating static files IMHO, so it's automatic,

Yeah this could be a solution too (however I think that json file is the better one because the json could change within the project)
I tried to cache the request in nginx but I was not able to do that (I'm not an nginx expert), if you could help it would be really appreciated. We are using your docker-compose solution, so a improvement there could be the better way.

[gioman]

@Gustry seen you have added the sponsor needed label, which is great. What would be the plan? Patch QGIS Server? Cache the legends? Create static legends with the LM plugin?

[nboisteault]

I think we could at least use etags for the GetLegendGraphic request but issues will happen if legends change with data changes. Most of the time legends are static so we might need an option to always cache by default and allow to not cache.
cc @rldhont

[gianvav]

Legends may change when you update the project, in style, in order, and when new layers are added.

It would be great if the getLegendGraphic request to be cached is generated when the cfg file is saved together with the project, considering a warning when saving the project having modified the layer tree.

[nboisteault]

@lucadelu Do you have a project to reproduce the issue? We don't have this slowness problem with clients hosted on 3Liz servers.

[gianvav]

here
https://provinciadilatina.gishosting.eu/index.php/view/map?repository=webgis&project=SIT

[Gustry]

Can you have some QGIS logs (with verbosity) for the GetLegendGraphic ? There should be a bottleneck somewhere

[nboisteault]

here https://provinciadilatina.gishosting.eu/index.php/view/map?repository=webgis&project=SIT

27s / 167 nodes = 160ms per node

With another test where I just take 10 nodes : 5s / 10 nodes = 500 ms per node

There is something wrong server side but you'll need to monitor/benchmark as we don't have those values on our servers.

[Gustry]

@Gustry seen you have added the sponsor needed label, which is great

Any help : either technically on the source code (some debug would be nice, to first check where is the bottleneck, adding some verbosity in logs, doing a "profiling" to see where the time is spent in the process) or financially if it's really an issue.

We have more customers on 3.7 than 3.6 now, we didn't experience this issue so far, with such big delay.

[gianvav]

waiting @lucadelu for the log file, I checked the getLegendGraphic request for each layer and put the results into a CSV
response_times.csv
getLegendGraphic_layers_response.xlsx

As you can see, the categorized and rule-categorized layers are the most time-consuming.

I also noticed that when the user load is high the average request time increases

[lucadelu]

Can you have some QGIS logs (with verbosity) for the GetLegendGraphic ? There should be a bottleneck somewhere

Sorry for delay, here you are a log file when people access to the project (it is repeated twice)

Responding also to @nboisteault our system is based on this compose-file, the server is quite powerfull more than 100GB ram 12 cpu and the server load is really low, I never seen it more the 5. I also customized postgresql, nginx and pyqgis-server adding more capabilities but this only mitigated a little bit but it not solved the problem.

Thanks a lot

log_pyqgis.txt

[lucadelu]

@Gustry seen you have added the sponsor needed label, which is great

Any help : either technically on the source code (some debug would be nice, to first check where is the bottleneck, adding some verbosity in logs, doing a "profiling" to see where the time is spent in the process) or financially if it's really an issue.

We have more customers on 3.7 than 3.6 now, we didn't experience this issue so far, with such big delay.

@Gustry can you help me to provide any good profile?

However if you think the creation of json file in the plugin could be a solution, I can work on the plugin side if someone will work on the lizmap client side...

[SecondGIS]

here https://provinciadilatina.gishosting.eu/index.php/view/map?repository=webgis&project=SIT

Hi there, I just clicked the link and could open your map in one second ! How did you fix your issue ?
Thanks for sharing

[lucadelu]

Dear @SecondGIS we solved the problem changing the QGIS container we switch from the py-qgis-server released from 3liz to a normal QGIS server container and everything came back to normality, so the problem seems more related to py-qgis-server than lizmap it self.

[Gustry]

Hum, strange...
Do you have an idea if it's only related to docker or to the Py-QGIS-Server overlay ?

@lucadelu You are not using Py-QGIS-Server anymore ?

We are going to release/promote https://github.com/3liz/py-qgis-server2 It has been totally rewritten.

CC @dmarteau

[Gustry]

@lucadelu Please copy/paste your versions by doing a right click step on your server. (even with the actual QGIS container)
https://docs.lizmap.com/current/en/publish/lizmap_plugin/information.html#request-for-support

[Gustry]

Or @SecondGIS or @mind84 for your versions.

[SecondGIS]

@Gustry here are the versions I'm using :

Lizmap Web Client : 3.7.10
Lizmap plugin : 4.3.24
QGIS Desktop : 3.28.15
QGIS Server : 3.28.13
Py-QGIS-Server : 1.8.8
QGIS Server plugin atlasprint : 3.3.2
QGIS Server plugin lizmap_server : 2.10.0
QGIS Server plugin wfsOutputExtension : 1.8.0

Should I change py-qgis-server to the version mentioned above ? Can I change this component only and how to do it ?
Thanks for your answers

[Gustry]

Lizmap Web Client : 3.7.10
QGIS Server : 3.28.13

We got a lot of bottlenecks with the duo QGIS 3.28 and LWC 3.7.

Lizmap Web Client >= 3.7 is better served with QGIS Server 3.34 now.

[SecondGIS]

Lizmap Web Client >= 3.7 is better served with QGIS Server 3.34 now.

@Gustry thanks for your advice.
After upgrading QGis-server to 3.34, we are still facing the same GetLegendGraphic request bottleneck (19s).
Any idea what to try next ? py-qgis-server is mentioned above in the conversation, is there anything we can do about it ?
Or any other suggestion ?
Thank you very much for your help.

Dear @SecondGIS we solved the problem changing the QGIS container we switch from the py-qgis-server released from 3liz to >a normal QGIS server container and everything came back to normality, so the problem seems more related to py-qgis-server >than lizmap it self.

@lucadelu thank you too for answering ; any tip on how to switch to normal QGis container instead of py-qgis if it is the only solution before downgrading ?

[dmarteau]

Lizmap Web Client >= 3.7 is better served with QGIS Server 3.34 now.

Dear @SecondGIS we solved the problem changing the QGIS container we switch from the py-qgis-server released from 3liz to >a normal QGIS server container and everything came back to normality, so the problem seems more related to py-qgis-server >than lizmap it self.

Plz, look at the logs of the py-qgis-server container and check the response time directly from py-qgis-server. Another good way to debug issues is to send your requests directly to the py-qgis-server (as regular OWS request) and check logs and response.

[SecondGIS]

@dmarteau thanks for your answer. I am still trying to locate py-qgis-server log files. I could find opt/local/pyqgisserver/ in my Lizmap container, which seems to be where qgisserver is located, but that's all...
As to sending OWS requests directly to py-qgis-server, I have no idea how to do this. Any further help would be appreciated. Thank you very much.

[dmarteau]

@dmarteau thanks for your answer. I am still trying to locate py-qgis-server log files. I could find opt/local/pyqgisserver/ in my Lizmap container, which seems to be where qgisserver is located, but that's all...

py-qgis-server log on stderr, if your are using a Docker container inspect the container logs.

As to sending OWS requests directly to py-qgis-server, I have no idea how to do this. Any further help would be appreciated. Thank you very much.

Depends on your configuration, if you are using a container: publish the port on your host and send request to this port with curl or from any browser - (the map-server container expose the port 8080 internally)

[SecondGIS]

Here is a sample of the qgis-server container log (I cannot redirect those logs to a file for now, permission issue ?) :

2024-09-19 06:33:14,917 RREQ [1] 200 GET http://map:8080/ows/?FORMAT=application%2Fjson&LAYER=*layer*_3_2&MAP=*folder*%2F*qgis-project*.qgs&REQUEST=getlegendgraphic&SERVICE=WMS&STYLES=d%C3%A9faut&VERSION=1.3.0&LIZMAP_USER=&LIZMAP_USER_GROUPS= 1195 4097
2024-09-19 06:33:14,919 REQ [1] ip-address 200 POST /ows/ 1197 4097 3.7.10
2024-09-19 06:33:14,921 DEBUG [27] READY b'SND worker'
2024-09-19 06:33:14,924 DEBUG [27] REQUEST b'OWS-SERVER-1' b'OWS server 1'
2024-09-19 06:33:14,924 DEBUG [27] SND client: b'OWS-SERVER-1' -> worker: b'SND worker' : b'OWS server 1'
2024-09-19 06:33:14,925 DEBUG [35] RCV b'OWS-SERVER-1': b'OWS server 1'
2024-09-19 06:33:14,926 DEBUG [35] Handling request: b'OWS server 1'
2024-09-19 06:33:14,927 DEBUG [35] Resolving 'file' protocol for 'folder/qgis-project.qgs'
2024-09-19 06:33:14,930 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 06:33:14,930 DEBUG [35] Qgis: Lizmap: No lizmap user groups in request headers
2024-09-19 06:33:14,930 DEBUG [35] Qgis: Lizmap: Lizmap user groups in parameters :
2024-09-19 06:33:14,931 DEBUG [35] Qgis: Lizmap: Fetching /srv/projects/folder/qgis-project.qgs.cfg cfg file with last modified timestamp : 1726655006.0
2024-09-19 06:33:14,931 DEBUG [35] Qgis: Lizmap: No acl defined in Lizmap config
2024-09-19 06:33:14,932 DEBUG [35] Qgis: WfsOutputExtension: requestReady ran in 0.0s
2024-09-19 06:33:14,932 DEBUG [35] Qgis: Server: FORMAT:application/json
2024-09-19 06:33:14,932 DEBUG [35] Qgis: Server: LAYER:layer_3_1
2024-09-19 06:33:14,933 DEBUG [35] Qgis: Server: LIZMAP_USER:
2024-09-19 06:33:14,933 DEBUG [35] Qgis: Server: LIZMAP_USER_GROUPS:
2024-09-19 06:33:14,933 DEBUG [35] Qgis: Server: MAP:folder/qgis-project.qgs
2024-09-19 06:33:14,933 DEBUG [35] Qgis: Server: REQUEST:getlegendgraphic
2024-09-19 06:33:14,934 DEBUG [35] Qgis: Server: SERVICE:WMS
2024-09-19 06:33:14,934 DEBUG [35] Qgis: Server: STYLES:défaut
2024-09-19 06:33:14,934 DEBUG [35] Qgis: Server: VERSION:1.3.0
2024-09-19 06:33:14,936 DEBUG [35] Qgis: AccessControlFilter: QgsAccessControlFilter plugin default layerPermissions called
2024-09-19 06:33:14,936 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 06:33:14,937 DEBUG [35] Qgis: Lizmap: No lizmap user groups in request headers
2024-09-19 06:33:14,937 DEBUG [35] Qgis: Lizmap: Lizmap user groups in parameters :
2024-09-19 06:33:14,937 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 06:33:14,938 DEBUG [35] Qgis: Lizmap: No lizmap user login in request headers
2024-09-19 06:33:14,938 DEBUG [35] Qgis: Lizmap: Lizmap user login in parameters :
2024-09-19 06:33:14,939 DEBUG [35] Qgis: Lizmap: Fetching /srv/projects/folder/qgis-project.qgs.cfg cfg file with last modified timestamp : 1726655006.0
2024-09-19 06:33:14,939 DEBUG [35] Qgis: Lizmap: Lizmap config has no editionLayers
2024-09-19 06:33:14,940 DEBUG [35] Qgis: Lizmap: No Lizmap layer group visibility for: cat : item (group)
2024-09-19 06:33:14,940 DEBUG [35] Qgis: AccessControlFilter: QgsAccessControlFilter plugin default layerPermissions called
2024-09-19 06:33:14,941 DEBUG [35] Qgis: Server: WMS Request parameters:
2024-09-19 06:33:14,941 DEBUG [35] Qgis: Server: - LAYER : layer_3_1
2024-09-19 06:33:14,941 DEBUG [35] Qgis: Server: - STYLES : défaut
2024-09-19 06:33:14,942 DEBUG [35] Qgis: Server: - FORMAT : application/json
2024-09-19 06:33:14,942 DEBUG [35] Qgis: Server: - VERSION : 1.3.0
QFont::fromString: Invalid description '(empty)'
QFont::fromString: Invalid description '(empty)'
2024-09-19 06:33:15,130 DEBUG [35] Qgis: WfsOutputExtension: responseComplete ran in 0.0s
2024-09-19 06:33:15,135 DEBUG [35] b'SND worker': Flushing response data: (391 bytes)
2024-09-19 06:33:15,136 DEBUG [35] Sending bytes 391 (send_more: False)
2024-09-19 06:33:15,137 DEBUG [27] SND worker: b'SND worker' -> client: b'OWS-SERVER-1' : b'OWS server 1'
2024-09-19 06:33:15,137 DEBUG [35] Qgis: Server: Request finished in 207 ms

This part is repeated as many times as I have layers in my legend, taking a very long time in the end (this specific one was only 207ms but it can be up to 1200ms at least for other layers from what I could see).

[dmarteau]

This part is repeated as many times as I have layers

If I understand well, a request is sent for each layers ?

Qgis: Server: Request finished in 207 ms

This is a rather long time of processing but this come from the Qgis internal processing of the request: i.e Qgis takes 207ms to process the request. Take care that the first time, the project need to be loaded and that may takes some time.

I suspect a misconfiguration or a plugin issue. Can you run the py-qgis-server without any plugins and check for response time ?

[dmarteau]

And send the request directly to the qgis server, don't go through Lizmap.

[SecondGIS]

Here is the result to the GetCapabilities request sent directly to qgis-server with curl (from the host where the container is running, I didn't "unplug" plugins) :

2024-09-19 09:34:09,252 DEBUG [27] REQUEST b'OWS-SERVER-1' b'OWS server 1'
2024-09-19 09:34:09,252 DEBUG [27] SND client: b'OWS-SERVER-1' -> worker: b'SND worker' : b'OWS server 1'
2024-09-19 09:34:09,252 DEBUG [35] RCV b'OWS-SERVER-1': b'OWS server 1'
2024-09-19 09:34:09,253 DEBUG [35] Handling request: b'OWS server 1'
2024-09-19 09:34:09,253 DEBUG [35] Resolving 'file' protocol for 'folder/qgis-project.qgs'
2024-09-19 09:34:09,255 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 09:34:09,255 DEBUG [35] Qgis: Lizmap: No lizmap user groups in request headers
2024-09-19 09:34:09,255 DEBUG [35] Qgis: WfsOutputExtension: requestReady ran in 0.0s
2024-09-19 09:34:09,255 DEBUG [35] Qgis: Server: MAP:folder/qgis-project.qgs
2024-09-19 09:34:09,255 DEBUG [35] Qgis: Server: REQUEST:GetCapabilities
2024-09-19 09:34:09,255 DEBUG [35] Qgis: Server: SERVICE:WMS
2024-09-19 09:34:09,255 DEBUG [35] Qgis: Server: VERSION:1.3.0
2024-09-19 09:34:09,256 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 09:34:09,256 DEBUG [35] Qgis: Lizmap: No lizmap user groups in request headers
2024-09-19 09:34:09,257 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 09:34:09,257 DEBUG [35] Qgis: Lizmap: No lizmap user groups in request headers
2024-09-19 09:34:09,257 WARNING [35] Qgis: Server: Found WMS capabilities document in cache
2024-09-19 09:34:09,263 DEBUG [35] Qgis: WfsOutputExtension: responseComplete ran in 0.0s
2024-09-19 09:34:09,263 DEBUG [35] b'SND worker': Flushing response data: (70512 bytes)
2024-09-19 09:34:09,263 DEBUG [35] Sending bytes 70512 (send_more: False)
2024-09-19 09:34:09,264 DEBUG [35] Qgis: Server: Request finished in 9 ms
2024-09-19 09:34:09,264 DEBUG [27] SND worker: b'SND worker' -> client: b'OWS-SERVER-1' : b'OWS server 1'
2024-09-19 09:34:09,265 DEBUG [27] READY b'SND worker'
2024-09-19 09:34:09,265 RREQ [1] 200 GET http://127.0.0.1:8091/ows/?SERVICE=WMS&REQUEST=GetCapabilities&VERSION=1.3.0&MAP=*folder*%2F*qgis-project*.qgs 14 70512
2024-09-19 09:34:09,266 REQ [1] ip-address 200 GET /ows?SERVICE=WMS&REQUEST=GetCapabilities&VERSION=1.3.0&MAP=folder%2Fqgis-project.qgs 15 70512 curl/7.88.1

I don't know if it helps, until now I could not reproduce the whole process of the GetLegend request with curl.
Thanks for your help.

[dmarteau]

This is a specific problem with GetLendGraphic. Can you test with FORMAT=image/png instead of application/json ?

[SecondGIS]

Here is the GetLegendGraphic for one specific LAYER with FORMAT=application/json :

2024-09-19 10:48:29,863 DEBUG [27] REQUEST b'OWS-SERVER-1' b'\xb5\x1c\xec\xb0vt\x11\xef\x83\x04\x02B\xac\x14\x00\x02'
2024-09-19 10:48:29,864 DEBUG [27] SND client: b'OWS-SERVER-1' -> worker: b'\x02h\xf3\x8cu\x90\x11\xef\xb3\xc4\x02B\xac\x14\x00\x02' : b'\xb5\x1c\xec\xb0vt\x11\xef\x83\x04\x02B\xac\x14\x00\x02'
2024-09-19 10:48:29,864 DEBUG [35] RCV b'OWS-SERVER-1': b'\xb5\x1c\xec\xb0vt\x11\xef\x83\x04\x02B\xac\x14\x00\x02'
2024-09-19 10:48:29,864 DEBUG [35] Handling request: b'\xb5\x1c\xec\xb0vt\x11\xef\x83\x04\x02B\xac\x14\x00\x02'
2024-09-19 10:48:29,864 DEBUG [35] Resolving 'file' protocol for 'folder/qgis-project.qgs'
2024-09-19 10:48:29,865 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 10:48:29,866 DEBUG [35] Qgis: Lizmap: No lizmap user groups in request headers
2024-09-19 10:48:29,866 DEBUG [35] Qgis: WfsOutputExtension: requestReady ran in 0.0s
2024-09-19 10:48:29,866 DEBUG [35] Qgis: Server: FORMAT:application/json
2024-09-19 10:48:29,867 DEBUG [35] Qgis: Server: LAYER:layer_3_2
2024-09-19 10:48:29,867 DEBUG [35] Qgis: Server: MAP:folder/qgis-project.qgs
2024-09-19 10:48:29,867 DEBUG [35] Qgis: Server: REQUEST:GetLegendGraphic
2024-09-19 10:48:29,868 DEBUG [35] Qgis: Server: SERVICE:WMS
2024-09-19 10:48:29,868 DEBUG [35] Qgis: Server: STYLES:défaut
2024-09-19 10:48:29,868 DEBUG [35] Qgis: Server: VERSION:1.3.0
2024-09-19 10:48:29,870 DEBUG [35] Qgis: AccessControlFilter: QgsAccessControlFilter plugin default layerPermissions called
2024-09-19 10:48:29,870 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 10:48:29,870 DEBUG [35] Qgis: Lizmap: No lizmap user groups in request headers
2024-09-19 10:48:29,870 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 10:48:29,871 DEBUG [35] Qgis: Lizmap: No lizmap user login in request headers
2024-09-19 10:48:29,871 DEBUG [35] Qgis: Lizmap: Fetching /srv/projects/folder/qgis-project.qgs.cfg cfg file with last modified timestamp : 1726655006.0
2024-09-19 10:48:29,872 DEBUG [35] Qgis: AccessControlFilter: QgsAccessControlFilter plugin default layerPermissions called
2024-09-19 10:48:29,872 DEBUG [35] Qgis: Server: WMS Request parameters:
2024-09-19 10:48:29,872 DEBUG [35] Qgis: Server: - LAYER : layer_3_2
2024-09-19 10:48:29,872 DEBUG [35] Qgis: Server: - STYLES : défaut
2024-09-19 10:48:29,873 DEBUG [35] Qgis: Server: - FORMAT : application/json
2024-09-19 10:48:29,873 DEBUG [35] Qgis: Server: - VERSION : 1.3.0
QFont::fromString: Invalid description '(empty)'
QFont::fromString: Invalid description '(empty)'
2024-09-19 10:48:31,019 DEBUG [35] Qgis: WfsOutputExtension: responseComplete ran in 0.0s
2024-09-19 10:48:31,024 DEBUG [35] b'\x02h\xf3\x8cu\x90\x11\xef\xb3\xc4\x02B\xac\x14\x00\x02': Flushing response data: (4097 bytes)
2024-09-19 10:48:31,025 DEBUG [35] Sending bytes 4097 (send_more: False)
2024-09-19 10:48:31,025 DEBUG [35] Qgis: Server: Request finished in 1159 ms
2024-09-19 10:48:31,026 DEBUG [27] SND worker: b'\x02h\xf3\x8cu\x90\x11\xef\xb3\xc4\x02B\xac\x14\x00\x02' -> client: b'OWS-SERVER-1' : b'\xb5\x1c\xec\xb0vt\x11\xef\x83\x04\x02B\xac\x14\x00\x02'
2024-09-19 10:48:31,026 DEBUG [27] READY b'\x02h\xf3\x8cu\x90\x11\xef\xb3\xc4\x02B\xac\x14\x00\x02'
2024-09-19 10:48:31,028 RREQ [1] 200 GET http://127.0.0.1:8091/ows/?SERVICE=WMS&REQUEST=GetLegendGraphic&VERSION=1.3.0&MAP=*folder*%2F*qgis-project*.qgs&LAYER=*layer*_3_2&STYLES=d%C3%A9faut&FORMAT=application%2Fjson 1165 4097
2024-09-19 10:48:31,030 REQ [1] ip-address 200 GET /ows?SERVICE=WMS&REQUEST=GetLegendGraphic&VERSION=1.3.0&MAP=folder%2Fqgis-project.qgs&LAYER=layer_3_2&STYLES=d%C3%A9faut&FORMAT=application%2Fjson 1168 4097 curl/7.88.1

And now same LAYER with FORMAT=image/png :

2024-09-19 11:16:22,950 DEBUG [27] REQUEST b'OWS-SERVER-1' b'\x9aY\xc2\xb4vx\x11\xef\x83\x04\x02B\xac\x14\x00\x02'
2024-09-19 11:16:22,951 DEBUG [27] SND client: b'OWS-SERVER-1' -> worker: b'\x02h\xf3\x8cu\x90\x11\xef\xb3\xc4\x02B\xac\x14\x00\x02' : b'\x9aY\xc2\xb4vx\x11\xef\x83\x04\x02B\xac\x14\x00\x02'
2024-09-19 11:16:22,952 DEBUG [35] RCV b'OWS-SERVER-1': b'\x9aY\xc2\xb4vx\x11\xef\x83\x04\x02B\xac\x14\x00\x02'
2024-09-19 11:16:22,952 DEBUG [35] Handling request: b'\x9aY\xc2\xb4vx\x11\xef\x83\x04\x02B\xac\x14\x00\x02'
2024-09-19 11:16:22,954 DEBUG [35] Resolving 'file' protocol for 'folder/qgis-project.qgs'
2024-09-19 11:16:22,956 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 11:16:22,957 DEBUG [35] Qgis: Lizmap: No lizmap user groups in request headers
2024-09-19 11:16:22,957 DEBUG [35] Qgis: WfsOutputExtension: requestReady ran in 0.0s
2024-09-19 11:16:22,957 DEBUG [35] Qgis: Server: FORMAT:image/png
2024-09-19 11:16:22,957 DEBUG [35] Qgis: Server: LAYER:layer_3_2
2024-09-19 11:16:22,957 DEBUG [35] Qgis: Server: MAP:folder/qgis-project.qgs
2024-09-19 11:16:22,957 DEBUG [35] Qgis: Server: REQUEST:GetLegendGraphic
2024-09-19 11:16:22,957 DEBUG [35] Qgis: Server: SERVICE:WMS
2024-09-19 11:16:22,957 DEBUG [35] Qgis: Server: STYLES:défaut
2024-09-19 11:16:22,958 DEBUG [35] Qgis: Server: VERSION:1.3.0
2024-09-19 11:16:22,960 DEBUG [35] Qgis: AccessControlFilter: QgsAccessControlFilter plugin default layerPermissions called
2024-09-19 11:16:22,960 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 11:16:22,960 DEBUG [35] Qgis: Lizmap: No lizmap user groups in request headers
2024-09-19 11:16:22,960 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 11:16:22,960 DEBUG [35] Qgis: Lizmap: No lizmap user login in request headers
2024-09-19 11:16:22,961 DEBUG [35] Qgis: Lizmap: Fetching /srv/projects/folder/qgis-project.qgs.cfg cfg file with last modified timestamp : 1726655006.0
2024-09-19 11:16:22,961 DEBUG [35] Qgis: AccessControlFilter: QgsAccessControlFilter plugin default layerPermissions called
2024-09-19 11:16:22,962 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 11:16:22,962 DEBUG [35] Qgis: Lizmap: No lizmap user groups in request headers
2024-09-19 11:16:22,962 DEBUG [35] Qgis: Server: WMS Request parameters:
2024-09-19 11:16:22,962 DEBUG [35] Qgis: Server: - LAYER : layer_3_2
2024-09-19 11:16:22,962 DEBUG [35] Qgis: Server: - STYLES : défaut
2024-09-19 11:16:22,962 DEBUG [35] Qgis: Server: - FORMAT : image/png
2024-09-19 11:16:22,963 DEBUG [35] Qgis: Server: - VERSION : 1.3.0
QFont::fromString: Invalid description '(empty)'
QFont::fromString: Invalid description '(empty)'
QPainter::scale: Painter not active
2024-09-19 11:16:22,991 DEBUG [35] Qgis: Lizmap: Request headers provided
2024-09-19 11:16:22,991 DEBUG [35] Qgis: Lizmap: No lizmap user groups in request headers
2024-09-19 11:16:22,991 DEBUG [35] Qgis: WfsOutputExtension: responseComplete ran in 0.0s
2024-09-19 11:16:22,992 DEBUG [35] b'\x02h\xf3\x8cu\x90\x11\xef\xb3\xc4\x02B\xac\x14\x00\x02': Flushing response data: (11346 bytes)
2024-09-19 11:16:22,992 DEBUG [35] Sending bytes 11346 (send_more: False)
2024-09-19 11:16:22,992 DEBUG [35] Qgis: Server: Request finished in 36 ms
2024-09-19 11:16:22,993 DEBUG [27] SND worker: b'\x02h\xf3\x8cu\x90\x11\xef\xb3\xc4\x02B\xac\x14\x00\x02' -> client: b'OWS-SERVER-1' : b'\x9aY\xc2\xb4vx\x11\xef\x83\x04\x02B\xac\x14\x00\x02'
2024-09-19 11:16:22,994 DEBUG [27] READY b'\x02h\xf3\x8cu\x90\x11\xef\xb3\xc4\x02B\xac\x14\x00\x02'
2024-09-19 11:16:22,994 RREQ [1] 200 GET http://127.0.0.1:8091/ows/?SERVICE=WMS&REQUEST=GetLegendGraphic&VERSION=1.3.0&MAP=*folder*%2F*qgis-project*.qgs&LAYER=*layer*_3_2&STYLES=d%C3%A9faut&FORMAT=image%2Fpng 44 11346
2024-09-19 11:16:22,995 REQ [1] ip-address 200 GET /ows?SERVICE=WMS&REQUEST=GetLegendGraphic&VERSION=1.3.0&MAP=folder%2Fqgis-project.qgs&LAYER=layer_3_2&STYLES=d%C3%A9faut&FORMAT=image%2Fpng 46 11346 curl/7.88.1

I didn't include LIZMAP_USER and LIZMAP_USER_GROUPS parameters I guess it doesn't really matter here

[dmarteau]

Ok, we have 1165ms for application/json and 44ms for image/png (not sure if there is some caching involved).
There is definitely something wrong with the json production.

[dmarteau]

FYI:

• application/json: 2024-09-19 10:48:31,025 DEBUG [35] Qgis: Server: Request finished in 1159 ms
• image/png: Qgis: Server: Request finished in 36 ms

We need to investigate why Qgis has so much hard time to process application/json response

[SecondGIS]

Thanks for your attention and help.
Is there anything else I can do to help and provide more information ?

[dmarteau]

Can you provide the py-qgis-server image used ? (at least the version of py-qgis-server and QGIS
This may be done with: docker run -it 3liz/qgis-map-server:<image_tag> version

[SecondGIS]

command returns 3.34.8-1.8.8

[lucadelu]

@lucadelu Please copy/paste your versions by doing a right click step on your server. (even with the actual QGIS container) https://docs.lizmap.com/current/en/publish/lizmap_plugin/information.html#request-for-support

I have no any instance running now so I cannot tell you the problem, but I had with qgis version 3.28 and 3.34 and with several py-qgis-server versions

[lucadelu]

@lucadelu thank you too for answering ; any tip on how to switch to normal QGis container instead of py-qgis if it is the only solution before downgrading ?

we started from this and adapted to our case

[SecondGIS]

Issue not solved and confirmed today with steps easy to reproduce : see #4750 for more details.