Rendering of mapnik-layer hangs with mod_wsgi deployment about mapproxy HOT 10 CLOSED

Please run it with mapproxy-util serve-develop and post the error message.

from mapproxy.

Well, that's the thing -- there is no error. Everything wors as expected when running with mapproxy-util:

forstw@mapsrv02:~/mapproxy> mapproxy-util serve-develop mapproxy_testing.yaml
[2013-04-05 09:40:49,219] mapproxy.config - INFO - reading: /home/forstw/mapproxy/mapproxy_testing.yaml
[2013-04-05 09:40:49,271] mapproxy.system - INFO - loading proj data from /home/forstw/mapproxy/.
/usr/lib64/python2.7/site-packages/mapnik2/__init__.py:27: DeprecationWarning:  mapnik2 module has been deprecated,
        please use 'import mapnik' 
  warnings.warn(msg, DeprecationWarning)
[info]  * Running on http://127.0.0.1:8080/
[info]  * Restarting with reloader: stat() polling
[2013-04-05 09:40:49,485] mapproxy.config - INFO - reading: /home/forstw/mapproxy/mapproxy_testing.yaml
[2013-04-05 09:40:49,537] mapproxy.system - INFO - loading proj data from /home/forstw/mapproxy/.
/usr/lib64/python2.7/site-packages/mapnik2/__init__.py:27: DeprecationWarning:  mapnik2 module has been deprecated,
        please use 'import mapnik' 
  warnings.warn(msg, DeprecationWarning)
/usr/local/lib/python2.7/site-packages/mapproxy/source/mapnik.py:100: DeprecationWarning: 'Envelope' is deprecated and will be removed in Mapnik 3.x, use 'Box2d' instead
  envelope = self.mapnik.Envelope(*query.bbox)
[2013-04-05 09:41:08,175] mapproxy.source.request - INFO - API osm_overlay.xml:(1089686.2752334725,6099063.360930785,1180187.7167231196,6189564.802420432):EPSG:900913:(1184,1184) 200 950.3 2000
[2013-04-05 09:41:08,326] mapproxy.source.request - INFO - API osm_overlay.xml:(1089686.2752334725,6020791.843966763,1180187.7167231196,6111293.285456413):EPSG:900913:(1184,1184) 200 920.8 2328
[info] 127.0.0.1 - - [05/Apr/2013 09:41:09] "GET /tiles/1.0.0/overlay_mapnik_EPSG900913/11/1082/711.png HTTP/1.0" 200 -
[info] 127.0.0.1 - - [05/Apr/2013 09:41:09] "GET /tiles/1.0.0/overlay_mapnik_EPSG900913/11/1081/715.png HTTP/1.0" 200 -
[info] 127.0.0.1 - - [05/Apr/2013 09:41:09] "GET /tiles/1.0.0/overlay_mapnik_EPSG900913/11/1082/714.png HTTP/1.0" 200 -
[info] 127.0.0.1 - - [05/Apr/2013 09:41:09] "GET /tiles/1.0.0/overlay_mapnik_EPSG900913/11/1082/713.png HTTP/1.0" 200 -
[info] 127.0.0.1 - - [05/Apr/2013 09:41:09] "GET /tiles/1.0.0/overlay_mapnik_EPSG900913/11/1082/715.png HTTP/1.0" 200 -
[info] 127.0.0.1 - - [05/Apr/2013 09:41:09] "GET /tiles/1.0.0/overlay_mapnik_EPSG900913/11/1082/712.png HTTP/1.0" 200 -

Only a few deprecation warnings, but nothing too bad.
Happens only with mod_wsgi. (Also: other layers from WMS and tile-sources work fine with mod_wsgi. It's only the combination of mod_wsgi and mapnik).

from mapproxy.

Strange. Can you search for the stacktrace of the internal error? /var/log/apache/error.log or in some mapproxy.log (when you have configured logging)?

from mapproxy.

The first time I access a tile (e.g. /mapproxy/tiles/1.0.0/overlay_mapnik_EPSG900913/13/4305/2855.png in the URL. I'm using nw as the origin), the request hangs for ever and never finishes. At least not for ~7 minutes when I finally give up.
The second time I access the same tile, the request still takes a pretty long time, but finally returns while the first request still hangs, I get this:

In apaches access-log:

95.115.52.192 - - [05/Apr/2013:10:54:26 +0200] "GET /mapproxy/tms/1.0.0/overlay_mapnik_EPSG900913/1/3/0.png HTTP/1.1" 500 14 "[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913" "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:19.0) Gecko/20100101 Firefox/19.0"

indicating a HTTP 500.

In apaches error-log:

[Fri Apr 05 10:55:25 2013] [error] [client 95.115.52.192] LockTimeout: another process is still running with our lock, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192] Traceback (most recent call last):, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]   File "/usr/local/lib/python2.7/site-packages/mapproxy/wsgiapp.py", line 166, in __call__, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]     resp = self.handlers[handler_name].handle(req), referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]   File "/usr/local/lib/python2.7/site-packages/mapproxy/service/base.py", line 30, in handle, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]     return handler(parsed_req), referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]   File "/usr/local/lib/python2.7/site-packages/mapproxy/service/tile.py", line 74, in map, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]     tile = layer.render(tile_request, use_profiles=tile_request.use_profiles, coverage=limit_to), referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]   File "/usr/local/lib/python2.7/site-packages/mapproxy/service/tile.py", line 265, in render, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]     tile = self.tile_manager.load_tile_coord(tile_coord, with_metadata=True), referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]   File "/usr/local/lib/python2.7/site-packages/mapproxy/cache/tile.py", line 105, in load_tile_coord, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]     created_tiles = creator.create_tiles([tile]), referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]   File "/usr/local/lib/python2.7/site-packages/mapproxy/cache/tile.py", line 227, in create_tiles, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]     created_tiles = self._create_meta_tiles(meta_tiles), referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]   File "/usr/local/lib/python2.7/site-packages/mapproxy/cache/tile.py", line 300, in _create_meta_tiles, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]     created_tiles.extend(self._create_meta_tile(meta_tile)), referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]   File "/usr/local/lib/python2.7/site-packages/mapproxy/cache/tile.py", line 307, in _create_meta_tile, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]     with self.tile_mgr.lock(main_tile):, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]   File "/usr/local/lib/python2.7/site-packages/mapproxy/platform/cpython/lock.py", line 42, in __enter__, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]     self.lock(), referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]   File "/usr/local/lib/python2.7/site-packages/mapproxy/platform/cpython/lock.py", line 72, in lock, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192]     raise LockTimeout('another process is still running with our lock'), referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913
[Fri Apr 05 10:55:26 2013] [error] [client 95.115.52.192] LockTimeout: another process is still running with our lock, referer: http://tiles-cache.mapsrv.[...]/mapproxy/demo/?tms_layer=overlay_mapnik&format=png&srs=EPSG%3A900913

mapproxy.log and source-requests.log don't change at all this occurs (but logging does work when accessing other layers).
I also noticed, that the postgresql process does not consume much CPU. When running with mapproxy-util, I can clearly see postgresql working (I use it as a rendering backend for mapnik). Not when I access with mod_wsgi.

EDIT: If it helps if I put a few log-outputs in sources/mapnik.py or something, just tell me where and I'll try that.

from mapproxy.

Ok. It seems that Mapnik hangs when running inside mod_wsgi for some reason. There was a similar report on the list a few month ago (http://lists.osgeo.org/pipermail/mapproxy/2012-August/001177.html) and there was a similar mail on the Mapnik mailing list (http://www.mail-archive.com/[email protected]/msg04024.html).

I'm afraid that I can't help you here without debugging this and finding the root cause of the hang.

from mapproxy.

Thanks for your hints. After googling a bit, I seem to have fixed the problem by chaning my mod_wsgi configuration to:

    LoadModule wsgi_module /usr/lib64/apache2/mod_wsgi.so
    WSGIScriptAlias /mapproxy /home/forstw/mapproxy/config.py
    WSGIDaemonProcess mapproxy-wsgi-daemon processes=16 threads=8
    WSGIApplicationGroup %{GLOBAL}
    
        Order deny,allow
        Allow from all
    

What finally fixed it was the WSGIApplicationGroup directive. Including this in the configuration fixed all problems.
You might want to add this as a note to the documentation if you want.

from mapproxy.

Great!

BTW: You need to set WSGIProcessGroup to make use of the configured WSGIDaemonProcess (see https://code.google.com/p/modwsgi/wiki/ConfigurationDirectives#WSGIDaemonProcess). Maybe then it works without the WSGIApplicationGroup.Can you verify that?

from mapproxy.

Setting WSGIProcessGroup but not WSGIApplicationGroup doesn't seem to help.
Setting both at the same time works fine again.
May I ask a quick question, even though it's a bit off topic?
I have a lot of pre-rendered tiles that were produced with OSM's gnerate_tiles.py (it's not OSM data. I used a cusom style-sheet. I only used generate_tiles.py to get the correct tile-dimensions, zooms, etc).
Quality of those tiles is perfect. Accessing them through mapproxy gives good results, everything is fine.
However, when I set the source-type to mapnik instead of tile and let mapproxy render the tiles for me, it doesn't look as good.
example:
http://abatzill.de/random/render.png
vs.
http://abatzill.de/random/prerender.png

In this case, the difference doesn't look that bad. But in other cases, it's hard to read the fonts when letting mapproxy do the rendering. Sometimes thin lines vanish completely when rendering with mapproxy.
I also tried different resampling methods, but they don't change the result.
Is there a way to get equivalent results for live-rendered tiles?

from mapproxy.

Thanks for testing this. I've updated the documentation e4a7af5.

For the tiles: It looks like PNG8 issue, see http://lists.osgeo.org/pipermail/mapproxy/2012-April/001054.html
So, disable platted images or upgrade PIL. (Just install Pillow 2.0, instead of my fork.)
If you need more help with this, then please join the mailing list.

from mapproxy.

I'll note that in my experience this wsgi modification is only needed if the lxml python bindings are used in the same process as Mapnik AND they are built --with-threading. So the problem lies not necessarily in mod_wsgi or in mapnik but rather in the interplay between lxml and libxml2 (the pure libxml2 C library is what Mapnik uses to load XML files). Since I have never seen anything like this outside of python my hunch is that lxml is to blame, or perhaps Mapnik's initialization of libxml2 is incorrect. For example, in Mapnik we do not call xmlInitParser() as is mentioned at http://www.xmlsoft.org/threads.html. But we've also never had a single report/known problem related to libxml2 and thread besides this python problem with lxml.

If anyone is able to isolate a testcase outside of mod_wsgi that can trigger a hang with lxml and mapnik are used, I would be interested to hear.

Also, I would be interested if this hang is possible to trigger in MapProxy if lxml is removed. I presume it is not, no matter what the mod_wsgi configurations are.

from mapproxy.