Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"Failed to read cmd on fd" errors since mod_tile update on 2nd June #77

Open
SomeoneElseOSM opened this issue Jun 9, 2014 · 16 comments

Comments

@SomeoneElseOSM
Copy link
Contributor

I have a fairly standard Ubuntu 14.04 based map server, set up as per http://wiki.openstreetmap.org/wiki/User:SomeoneElse/Ubuntu_1404_tileserver .

I installed it on 26th April, and everything worked as expected. On 2nd June I updated mod_tile from github and started seeing "Failed to read cmd on fd" errors in syslog:

Jun 9 12:20:52 ubuntuvm38 renderd[21354]: DEBUG: Got incoming request with protocol version 2
Jun 9 12:20:52 ubuntuvm38 renderd[21354]: DEBUG: Got command RenderPrio fd(14) xml(default), z(18), x(130734), y(85209), mime(image/png), options()
Jun 9 12:20:55 ubuntuvm38 renderd[21354]: DEBUG: DONE TILE default 18 130728-130735 85208-85215 in 2.407 seconds
Jun 9 12:20:55 ubuntuvm38 renderd[21354]: DEBUG: Sending render cmd(3 default 18/130735/85209) with protocol version 2 to fd 8
Jun 9 12:20:55 ubuntuvm38 renderd[21354]: DEBUG: Failed to read cmd on fd 8
Jun 9 12:20:55 ubuntuvm38 renderd[21354]: DEBUG: Connection 0, fd 8 closed, now 5 left

This doesn't stop it working (all tiles are still being rendered as expected) but it does seem odd. Other server updates between 26th April and 2nd June include Ubuntu apt-get updates, a database reload from a new PBF file, but no changes to osm2pgsql style or (presumably) database columns etc.

http://forum.openstreetmap.org/viewtopic.php?id=25587

(from May 23rd) looks like it might be a similar issue.

@milgner
Copy link

milgner commented Jul 26, 2014

Same here except that it's a new server and not working, but my output looks exactly like yours. This doesn't feel right...

@jburgess777
Copy link
Member

The "failed to read cmd" message was added by Kai in 9d4e10e. It will be triggered any time a connection is closed because recv() returns 0 for this case. I don't think it is any cause for concern but maybe we want to set this at LOG_DEBUG or differentiate between -1 (errors) and 0 (successful close).

@avirupd-egnaroinc
Copy link

I have followed this tutorial https://switch2osm.org/serving-tiles/manually-building-a-tile-server-14-04/
But I am getting this when I am running
sudo -u egnaro renderd -f -c /usr/local/etc/renderd.conf

renderd[22238]: Rendering daemon started
renderd[22238]: Initiating reqyest_queue
renderd[22238]: Parsing section renderd
renderd[22238]: Parsing render section 0
renderd[22238]: Parsing section renderd01
renderd[22238]: Parsing render section 1
renderd[22238]: Parsing section renderd02
renderd[22238]: Parsing render section 2
renderd[22238]: Parsing section mapnik
renderd[22238]: Parsing section default
renderd[22238]: Parsing section style2
renderd[22238]: config renderd: unix socketname=/var/run/renderd/renderd.sock
renderd[22238]: config renderd: num_threads=4
renderd[22238]: config renderd: num_slaves=8
renderd[22238]: config renderd: tile_dir=/var/lib/mod_tile
renderd[22238]: config renderd: stats_file=/var/run/renderd/renderd.stats
renderd[22238]: config mapnik: plugins_dir=/usr/local/lib/mapnik/input
renderd[22238]: config mapnik: font_dir=/usr/share/fonts/truetype/ttf-dejavu
renderd[22238]: config mapnik: font_dir_recurse=1
renderd[22238]: config renderd(0): Active
renderd[22238]: config renderd(0): unix socketname=/var/run/renderd/renderd.sock
renderd[22238]: config renderd(0): num_threads=4
renderd[22238]: config renderd(0): tile_dir=/var/lib/mod_tile
renderd[22238]: config renderd(0): stats_file=/var/run/renderd/renderd.stats
renderd[22238]: config renderd(1): unix socketname=/var/run/renderd/renderd.sock
renderd[22238]: config renderd(1): num_threads=4
renderd[22238]: config renderd(1): tile_dir=/var/lib/mod_tile
renderd[22238]: config renderd(1): stats_file=(null)
renderd[22238]: config renderd(2): unix socketname=/var/run/renderd/renderd.sock
renderd[22238]: config renderd(2): num_threads=4
renderd[22238]: config renderd(2): tile_dir=/var/lib/mod_tile
renderd[22238]: config renderd(2): stats_file=(null)
renderd[22238]: config map 0: name(default) file(/usr/local/share/maps/style/OSMBright/OSMBright.xml) uri(/osm_tiles/) htcp() host(localhost)
renderd[22238]: config map 1: name(style2) file() uri(/osm_tiles2/) htcp() host()
renderd[22238]: Initialising unix server socket on /var/run/renderd/renderd.sock
renderd[22238]: Created server socket 4
renderd[22238]: Renderd is using mapnik version 2.2.0
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSerifCondensed-Bold.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSansMono-Oblique.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSerif.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSansCondensed-Oblique.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSansCondensed-Bold.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSerifCondensed.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSansCondensed.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSerif-Italic.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSerifCondensed-BoldItalic.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSans.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSansCondensed-BoldOblique.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSans-BoldOblique.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSans-ExtraLight.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSans-Oblique.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSans-Bold.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSansMono-Bold.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSerif-Bold.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSerif-BoldItalic.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSansMono-BoldOblique.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSerifCondensed-Italic.ttf
renderd[22238]: DEBUG: Loading font: /usr/share/fonts/truetype/ttf-dejavu/DejaVuSansMono.ttf
Running in foreground mode...
renderd[22238]: Starting stats thread
renderd[22238]: Initialising unix client socket on /var/run/renderd/renderd.sock
renderd[22238]: socket /var/run/renderd/renderd.sock initialised to fd 5
renderd[22238]: Initialising unix client socket on /var/run/renderd/renderd.sock
renderd[22238]: socket /var/run/renderd/renderd.sock initialised to fd 6
debug: init_storage_backend: initialising file storage backend at: /var/lib/mod_tile
renderd[22238]: Initialising unix client socket on /var/run/renderd/renderd.sock
renderd[22238]: socket /var/run/renderd/renderd.sock initialised to fd 7
renderd[22238]: Loading parameterization function for debug: init_storage_backend: initialising file storage backend at: /var/lib/mod_tile

renderd[22238]: Initialising unix client socket on /var/run/renderd/renderd.sock
renderd[22238]: Initialising unix client socket on /var/run/renderd/renderd.sock
renderd[22238]: Loading parameterization function for
renderd[22238]: socket /var/run/renderd/renderd.sock initialised to fd 9
renderd[22238]: socket /var/run/renderd/renderd.sock initialised to fd 8
renderd[22238]: Initialising unix client socket on /var/run/renderd/renderd.sock
renderd[22238]: socket /var/run/renderd/renderd.sock initialised to fd 10
debug: init_storage_backend: initialising file storage backend at: /var/lib/mod_tile
renderd[22238]: Initialising unix client socket on /var/run/renderd/renderd.sockrenderd[22238]: DEBUG: Got incoming connection, fd 13, number 1

debug: init_storage_backend: initialising file storage backend at: /var/lib/mod_tile
renderd[22238]: DEBUG: Got incoming connection, fd 14, number 2
renderd[22238]: socket /var/run/renderd/renderd.sock initialised to fd 15renderd[22238]: DEBUG: Got incoming connection, fd 16, number 3

renderd[22238]: DEBUG: Got incoming connection, fd 17, number 4
renderd[22238]: DEBUG: Got incoming connection, fd 18, number 5
renderd[22238]: Initialising unix client socket on /var/run/renderd/renderd.sockrenderd[22238]: DEBUG: Got incoming connection, fd 19, number 6

renderd[22238]: Loading parameterization function for renderd[22238]: DEBUG: Got incoming connection, fd 20, number 7

renderd[22238]: Loading parameterization function for
renderd[22238]: socket /var/run/renderd/renderd.sock initialised to fd 21
renderd[22238]: DEBUG: Got incoming connection, fd 22, number 8
renderd[22238]: Using web mercator projection settings
renderd[22238]: Using web mercator projection settings
renderd[22238]: Using web mercator projection settings
renderd[22238]: Using web mercator projection settings
renderd[22238]: DEBUG: Got incoming connection, fd 23, number 9
renderd[22238]: DEBUG: Got incoming request with protocol version 2
renderd[22238]: DEBUG: Got command RenderLow fd(23) xml(default), z(0), x(0), y(0), mime(image/png), options()
renderd[22238]: DEBUG: Failed to read cmd on fd 23
renderd[22238]: DEBUG: Connection 8, fd 23 closed, now 8 left
renderd[22238]: Dispatching request to slave thread on fd 5
renderd[22238]: DEBUG: Sending render cmd(1 default 0/0/0) with protocol version 3 to fd 5
renderd[22238]: DEBUG: Got incoming request with protocol version 3
renderd[22238]: DEBUG: Got command Render fd(13) xml(default), z(0), x(0), y(0), mime(image/png), options()
renderd[22238]: DEBUG: Got incoming connection, fd 23, number 9
renderd[22238]: DEBUG: Got incoming request with protocol version 2
renderd[22238]: DEBUG: Got command RenderLow fd(23) xml(default), z(0), x(0), y(0), mime(image/png), options()
renderd[22238]: DEBUG: Failed to read cmd on fd 23
renderd[22238]: DEBUG: Connection 8, fd 23 closed, now 8 left
renderd[22238]: DEBUG: Got incoming connection, fd 23, number 9
renderd[22238]: DEBUG: Got incoming request with protocol version 2
renderd[22238]: DEBUG: Got command RenderLow fd(23) xml(default), z(0), x(0), y(0), mime(image/png), options()
renderd[22238]: DEBUG: Failed to read cmd on fd 23
renderd[22238]: DEBUG: Connection 8, fd 23 closed, now 8 left
renderd[22238]: DEBUG: Got incoming connection, fd 23, number 9
renderd[22238]: DEBUG: Got incoming request with protocol version 2
renderd[22238]: DEBUG: Got command RenderLow fd(23) xml(default), z(0), x(0), y(0), mime(image/png), options()
renderd[22238]: DEBUG: Failed to read cmd on fd 23
renderd[22238]: DEBUG: Connection 8, fd 23 closed, now 8 left
renderd[22238]: DEBUG: Got incoming connection, fd 23, number 9
renderd[22238]: DEBUG: Got incoming request with protocol version 2
renderd[22238]: DEBUG: Got command RenderLow fd(23) xml(default), z(0), x(0), y(0), mime(image/png), options()
renderd[22238]: DEBUG: Failed to read cmd on fd 23
renderd[22238]: DEBUG: Connection 8, fd 23 closed, now 8 left
renderd[22238]: DEBUG: Got incoming connection, fd 23, number 9
renderd[22238]: DEBUG: Got incoming request with protocol version 2
renderd[22238]: DEBUG: Got command RenderLow fd(23) xml(default), z(0), x(0), y(0), mime(image/png), options()
renderd[22238]: DEBUG: Failed to read cmd on fd 23
renderd[22238]: DEBUG: Connection 8, fd 23 closed, now 8 left

My renderd.conf file is as follows
[renderd]
socketname=/var/run/renderd/renderd.sock
num_threads=4
tile_dir=/var/lib/mod_tile
stats_file=/var/run/renderd/renderd.stats

[renderd01]
;iphostname=::1
;ipport=7654
;num_threads=4
;tile_dir=rados://tiles/etc/ceph/ceph.conf
;stats_file=/var/run/renderd/renderd.stats

[renderd02]
;iphostname=::1
;ipport=7654
;num_threads=8
;tile_dir=memcached://
;stats_file=/var/run/renderd/renderd.stats

[mapnik]
plugins_dir=/usr/local/lib/mapnik/input
font_dir=/usr/share/fonts/truetype/ttf-dejavu
font_dir_recurse=1

[default]
URI=/osm_tiles/
TILEDIR=/var/lib/mod_tile
XML=/usr/local/share/maps/style/OSMBright/OSMBright.xml
HOST=localhost
TILESIZE=256
;HTCPHOST=proxy.openstreetmap.org
;MINZOOM=0
;MAXZOOM=18
;TYPE=png image/png
;DESCRIPTION=This is a description of the tile layer used in the tile json request
;ATTRIBUTION=©<a href="http://www.openstreetmap.org/\">OpenStreetMap and <a href="http://wiki.openstreetmap.org/wiki/Contributors\">contributors, <a href="http://opendatacommons.org/licenses/odbl/\">ODbL
;SERVER_ALIAS=http://localhost/
;CORS=http://www.openstreetmap.org
;ASPECTX=1
;ASPECTY=1
;SCALE=1.0

[style2]
URI=/osm_tiles2/
;TILEDIR=rados://tiles/etc/ceph/ceph.conf
;TILESIZE=512
;XML=/home/jburgess/osm/svn.openstreetmap.org/applications/rendering/mapnik/osm-local2.xml
;HOST=tile.openstreetmap.org
;HTCPHOST=proxy.openstreetmap.org
;MINZOOM=0
;MAXZOOM=22
;TYPE=png image/png
;DESCRIPTION=This is a description of the tile layer used in the tile json request
;ATTRIBUTION=©<a href="http://www.openstreetmap.org/\">OpenStreetMap and <a href="http://wiki.openstreetmap.org/wiki/Contributors\">contributors, <a href="http://opendatacommons.org/licenses/odbl/\">ODbL
;SERVER_ALIAS=http://localhost/
;CORS=*

Please help me to know what I am doing wrong here.

@SomeoneElseOSM
Copy link
Contributor Author

@avirupd-egnaroinc I'll reply on https://lists.openstreetmap.org/listinfo/tile-serving to avoid everyone on Gihub seeing it.

@liaomeng
Copy link

help!! I have the same problem as @avirupd-egnaroinc.....Could anyone tell me the solution to this?

@SomeoneElseOSM
Copy link
Contributor Author

@liaomeng I replied to @avirupd-egnaroinc over on the tile-serving list. That's a better place than here for queries such as "I can't get this to work" (which in any case are unrelated to the issue here, which is that "Failed to read cmd on fd" messages are printed in a debug log, even when nothing is wrong).

I'd suggest that you post over there explaining what you've tried and what doesn't work. If you're unsure what information to provide try asking in the #osm or #osm-dev IRC channels on OFTC.

@cglacet
Copy link

cglacet commented Jun 11, 2017

I would be interested in possible ways of finding what's the problem too. I have a very similar problem (metatiles are rendered correctly but PNG fail to be served). I couldn't find your answer on the list.

@SomeoneElseOSM
Copy link
Contributor Author

@cglacet The reply to @liaomeng applies to you too I think - this specific issue is about "Failed to read cmd on fd" messages are printed in a debug log when nothing is wrong. That doesn't sound like your main problem.

@cglacet
Copy link

cglacet commented Jun 11, 2017

Sadly this is the only "bad thing" that seems to happen. I'm actually looking for a way to have any kind of debugging option (showing more debug messages would be nice) because I really have no idea what is happening, but renderD seems to never send anything to mod_tile (or apache I don't know). It may be a lot of things, but these tools are very laconic (or I have no idea on how to make them talk a bit to me).

Here is what is happening when the tile is built:

Jun 11 17:30:56  renderd[22663] <Debug>: Rendering projected coordinates 8 248 160 -> 18785164.071375|-6261721.357125 20037508.342800|-5009377.085700 to a 8 x 8 tile
Jun 11 17:31:00  renderd[22663] <Debug>: DEBUG: DONE TILE default 8 248-255 160-167 in 3.939 seconds
debug: Creating and writing a metatile to /var/lib/mod_tile/default/8/0/0/0/250/128.meta

Jun 11 17:31:00  renderd[22663] <Debug>: DEBUG: Sending render cmd(3 default 8/251/160) with protocol version 2 to fd 5
Jun 11 17:31:00  renderd[22663] <Info>: DEBUG: Failed to read cmd on fd 5
Jun 11 17:31:00  renderd[22663] <Debug>: DEBUG: Connection 0, fd 5 closed, now 0 left

@SomeoneElseOSM
Copy link
Contributor Author

You're seeing a "DEBUG: DONE TILE" message, which means that apache's sent the message via mod_tile to renderd, and renderd has created a metatile. You should be able to see a file in "/var/lib/mod_tile/default/8/0/0/0/250/128.meta" The fact that you can't then see that when you view it presumably in a web browser is a different issue - maybe there's a permissions issue somewhere, or whatever you've set up to view tiles isn't working.

The debug steps in https://switch2osm.org/manually-building-a-tile-server-16-04-2-lts/ may help a bit, specifically:

  1. Initiallly just try and view http://yourserveripaddress/hot/0/0/0.png (or whatever for your tile location)
  2. Run renderd in the foreground to see how it reacts to incoming commands
  3. Use something like “Switcheroo Redirector” to make your tiles appear via openstreetmap.org in Chrome or Chromium.

@cglacet
Copy link

cglacet commented Jun 11, 2017

  1. Is already what I've done (the metatile is perfectly fine, I checked using meta2tile).
  2. Is the output I pasted just before (it stops there). Or outputs nothing if I ask for the same tile again.
  3. I'll try that now, thank you.

Is that normal that mapnik doesn't output anything btw (renderd is just wrapping everything even the outputs)?

"maybe there's a permissions issue somewhere" yes maybe, is there anything in particular you have in mind? My metatiles are owned by my postgresql user (is that the correct way to do?). Here is how my rights are defined:

$ ls -la /var/lib/mod_tile/default/8/0/0/0/250/128.meta /var/run/renderd/

-rw-r--r-- 1 postgres wheel  317572 Jun 11 17:31 /var/lib/mod_tile/default/8/0/0/0/250/128.meta
/var/run/renderd/:
    drwxr-xr-x  5 postgres daemon  170 Jun 11 18:31 .
    drwxrwxr-x 33 root     daemon 1122 Jun 11 17:13 ..
    -rw-r--r--  1 postgres daemon    6 Jun 10 06:07 renderd.pid
    srwxrwxrwx  1 postgres daemon    0 Jun 11 18:16 renderd.sock
    -rw-r--r--  1 postgres daemon 1143 Jun 11 18:31 renderd.stats

$ ls -la /usr/libexec/apache2/mod_tile.so

-rw-r--r-- 1 root wheel 130596 Jun  7 20:27 /usr/libexec/apache2/mod_tile.so

$ ls -la /usr/local/lib/mapnik

lrwxr-xr-x 1 cglacet admin  34 Jun  7 15:05 /usr/local/lib/mapnik -> ../Cellar/mapnik/3.0.13/lib/mapnik

$ dscacheutil -q group | grep -E -A 3 'daemon|wheel'

name: daemon
password: *
gid: 1
users: root
--
name: wheel
password: *
gid: 0
users: root

The commands I run to get started are:

 $ sudo rm -rf /var/lib/mod_tile/default/*
 $ sudo bash -c 'echo -e "\c" > /var/log/apache2/error-mode_tile.log'
 $ sudo apachectl -k restart

and

 $ sudo -u postgres renderd -f -c /usr/local/etc/renderd.conf

Thank you again for helping me 👍


ps, Apache says this:

[Sun Jun 11 18:46:33.398094 2017] [tile:debug] [pid 25867] ./src/mod_tile.c(1289): [client ::1:58386] tile_translate: uri(/osm_tiles/8/251/160.png)
[Sun Jun 11 18:46:33.398104 2017] [tile:debug] [pid 25867] ./src/mod_tile.c(1306): [client ::1:58386] tile_translate: testing baseuri(/osm_tiles/) name(default) extension(png)
[Sun Jun 11 18:46:33.398123 2017] [tile:debug] [pid 25867] ./src/mod_tile.c(1352): [client ::1:58386] tile_translate: request for default was 251 160 256
[Sun Jun 11 18:46:33.398129 2017] [tile:debug] [pid 25867] ./src/mod_tile.c(324): [client ::1:58386] get_storage_backend: Retrieving storage back end for tile layer 0 in pool 7fb683827628 and thread -1075362880
[Sun Jun 11 18:46:33.398134 2017] [tile:debug] [pid 25867] ./src/mod_tile.c(338): [client ::1:58386] get_storage_backend: No storage backends for this lifecycle 7fb683827628, creating it in thread -1075362880
[Sun Jun 11 18:46:33.398138 2017] [tile:debug] [pid 25867] ./src/mod_tile.c(353): [client ::1:58386] get_storage_backend: No storage backend in current lifecycle 7fb683827628 in thread -1075362880 for current tile layer 0
[Sun Jun 11 18:46:33.398180 2017] [tile:debug] [pid 25867] ./src/mod_tile.c(1391): [client ::1:58386] tile_translate: op(tile_serve) xml(default) mime(image/png) z(8) x(251) y(160)
[Sun Jun 11 18:46:33.398188 2017] [tile:info] [pid 25867] [client ::1:58386] tile_storage_hook: handler(tile_serve), uri(/osm_tiles/8/251/160.png)
[Sun Jun 11 18:46:33.398213 2017] [tile:debug] [pid 25867] ./src/mod_tile.c(374): [client ::1:58386] tile_state: determined state of default 251 160 8 on store 7fb68340c000: Tile size: -1, expired: 1 created: 0
[Sun Jun 11 18:46:33.398220 2017] [tile:debug] [pid 25867] ./src/mod_tile.c(176): [client ::1:58386] Connecting to renderd on Unix socket /var/run/renderd/renderd.sock
[Sun Jun 11 18:46:33.398241 2017] [tile:info] [pid 25867] [client ::1:58386] Requesting style(default) z(8) x(251) y(160) from renderer with priority 5
[Sun Jun 11 18:46:39.541360 2017] [authz_core:debug] [pid 25867] mod_authz_core.c(834): [client ::1:58386] AH01628: authorization result: granted (no directives)
[Sun Jun 11 18:46:39.541421 2017] [core:trace3] [pid 25867] request.c(296): [client ::1:58386] request authorized without authentication by access_checker_ex hook: /osm_tiles/8/251/160.png

And for the second request (once the tile has been generated):

...
[Sun Jun 11 18:51:02.012422 2017] [tile:debug] [pid 25869] ./src/mod_tile.c(1391): [client ::1:59381] tile_translate: op(tile_serve) xml(default) mime(image/png) z(8) x(251) y(160)
[Sun Jun 11 18:51:02.012433 2017] [tile:info] [pid 25869] [client ::1:59381] tile_storage_hook: handler(tile_serve), uri(/osm_tiles/8/251/160.png)
[Sun Jun 11 18:51:02.012472 2017] [tile:debug] [pid 25869] ./src/mod_tile.c(374): [client ::1:59381] tile_state: determined state of default 251 160 8 on store 7fb68340bfc0: Tile size: 317572, expired: 0 created: 1497199599
[Sun Jun 11 18:51:02.012540 2017] [authz_core:debug] [pid 25869] mod_authz_core.c(834): [client ::1:59381] AH01628: authorization result: granted (no directives)
[Sun Jun 11 18:51:02.012555 2017] [core:trace3] [pid 25869] request.c(296): [client ::1:59381] request authorized without authentication by access_checker_ex hook: /osm_tiles/8/251/160.png

@SomeoneElseOSM
Copy link
Contributor Author

SomeoneElseOSM commented Jun 11, 2017

What OS are you using? In an apache error log with "loglevel debug" set I see a "tile_state:" line but none of the "authorization" stuff that you get. I'm using Ubuntu 16.04 on a server that exactly matches https://wiki.openstreetmap.org/wiki/User:SomeoneElse/Ubuntu_1604_tileserver_load (which is very similar to but a different style from https://switch2osm.org/manually-building-a-tile-server-16-04-2-lts/ ). Perhaps you've got some different Apache modules loaded, perhaps manually or perhaps automatically because you're using a different OS or have installed something else that depends on them.

I haven't been through the older instructions https://switch2osm.org/serving-tiles/manually-building-a-tile-server-14-04/ for a while, and I suspect that you aren't following that to the letter since it says to use Mapnik 2.2 and you're using Mapnik 3.0 :)

Edit: I'm guessing that you're the same person as behind https://stackoverflow.com/questions/44469364 and my answer there may also help (briefly - it's on MacOS, so either find a "soup to nuts" guide for that platform or run Ubuntu in a VM).

@cglacet
Copy link

cglacet commented Jun 11, 2017

I'm using OSX(10.12.4). The apache authorization stuff that I get is because my httpd.conf is loading mod_authz_core. The following line is displayed because I have LogLevel set to trace8 instead of debug.

Loaded Modules:
 core_module (static)
 so_module (static)
 http_module (static)
 mpm_prefork_module (static)
 authn_file_module (shared)
 authn_core_module (shared)
 authz_host_module (shared)
 authz_groupfile_module (shared)
 authz_user_module (shared)
 authz_core_module (shared)
 access_compat_module (shared)
 auth_basic_module (shared)
 reqtimeout_module (shared)
 ext_filter_module (shared)
 filter_module (shared)
 mime_module (shared)
 log_config_module (shared)
 env_module (shared)
 headers_module (shared)
 setenvif_module (shared)
 version_module (shared)
 slotmem_shm_module (shared)
 unixd_module (shared)
 status_module (shared)
 autoindex_module (shared)
 vhost_alias_module (shared)
 negotiation_module (shared)
 dir_module (shared)
 alias_module (shared)
 hfs_apple_module (shared)
 tile_module (shared)

The complete apache configuration I use is the default one for my os.

Ah, I forgot to say that I've tried to use kosmtik, just to check if mapnik works, and everything works just fine.

Concerning Switcheroo Redirector, I don't think this would help since it just seems to be an URL rewriting plugin, for now I only try a simple "http://localhost/osm_tiles/8/251/160.png" which always get an empty response (ERR_EMPTY_RESPONSE).

I'm guessing that the problem comes from mod_tile (rights as you suggested), but I'm not entirely sure. I'll dig into this and come back as soon as I have something new, hopefully an error message somewhere or with gdb.

@SomeoneElseOSM
Copy link
Contributor Author

@cglacet Actually I'm guessing that there's a problem at the apache side, given that you can create metatiles, convert them manually to tiles at view them!

@cglacet
Copy link

cglacet commented Jun 12, 2017

Ah, I think I found something. I found what a normal debug output is like, and it turns out there is something I'm completely missing:

[tile:info] [<pid>] tile_storage_hook: handler(tile_serve), uri(/osm_tiles/0/0/0.png)
[tile:debug] [<pid>] ./src/mod_tile.c(365): tile_state: determined state of default 0 0 0 on store 7f2cad89c790: Tile size: 8419, expired: 0 created: 1421366421
[authz_core:debug] [<pid>] mod_authz_core.c(828): AH01628: authorization result: granted (no directives)
[tile:debug] [<pid>] ./src/mod_tile.c(1183): tile_handler_serve: xml(default) z(0) x(0) y(0)

I never have tile_handler_serve in my log, I checked a bit deeper and the function is actually never called. Which is probably the reason why no tiles are ever served. I'm not sure to understand the process yet so I can't tell who is responsible for throwing that particular request.

The same bug I have also happens when I request "http://localhost/mod_tile":

[tile:debug] [pid 9785] ./src/mod_tile.c(1301): [client ::1:56175] tile_translate: uri(/mod_tile)
[tile:info] [pid 9785] [client ::1:56175] tile_translate: retrieving global mod_tile stats
[tile:info] [pid 9785] [client ::1:56175] tile_storage_hook: handler(tile_mod_stats), uri(/mod_tile)
[authz_core:debug] [pid 9785] mod_authz_core.c(834): [client ::1:56175] AH01628: authorization result: granted (no directives)
[core:trace3] [pid 9785] request.c(296): [client ::1:56175] request authorized without authentication by access_checker_ex hook: /mod_tile

And yes, I also asked the question on stackoverflow.

@cglacet
Copy link

cglacet commented Jun 12, 2017

I finally found who was guilty ! I tried to remove all hooks except the tile_handler_serve from mod_tile.c, then a bunch of things happened:

mod_hfs_apple2.c(145): [client ::1:65478] mod_hfs_apple: / is case-insensitive
mod_hfs_apple2.c(145): [client ::1:65478] mod_hfs_apple: /var/ is case-insensitive
d_hfs_apple2.c(145): [client ::1:65478] mod_hfs_apple: /Library/WebServer/Documents/ is case-insensitive
mod_hfs_apple2.c(145): [client ::1:65478] mod_hfs_apple: /Library/WebServer/CGI-Executables/ is case-insensitive
mod_hfs_apple2.c(145): [client ::1:65478] mod_hfs_apple: /usr/share/httpd/icons/ is case-insensitive
mod_hfs_apple2.c(145): [client ::1:65478] mod_hfs_apple: .*\\.\\.namedfork/ is case-sensitive
mod_hfs_apple2.c(363): [client ::1:65478] mod_hfs_apple: compare_paths / vs /Library/WebServer/Documents/osm_tiles/, related=1
mod_hfs_apple2.c(363): [client ::1:65478] mod_hfs_apple: compare_paths /var/ vs /Library/WebServer/Documents/osm_tiles/, related=0
mod_hfs_apple2.c(363): [client ::1:65478] mod_hfs_apple: compare_paths /Library/WebServer/Documents/ vs /Library/WebServer/Documents/osm_tiles/, related=1
mod_hfs_apple2.c(363): [client ::1:65478] mod_hfs_apple: compare_paths /Library/WebServer/CGI-Executables/ vs /Library/WebServer/Documents/osm_tiles/, related=0
mod_hfs_apple2.c(363): [client ::1:65478] mod_hfs_apple: compare_paths /usr/share/httpd/icons/ vs /Library/WebServer/Documents/osm_tiles/, related=0
mod_hfs_apple2.c(363): [client ::1:65478] mod_hfs_apple: compare_paths .*\\.\\.namedfork/ vs /Library/WebServer/Documents/osm_tiles/, related=0
mod_hfs_apple2.c(384): [client ::1:65478] mod_hfs_apple: Final check compares: /Library/WebServer/Documents/osm_tiles vs /Library/WebServer/Documents/, length 28
mod_hfs_apple2.c(397): [client ::1:65478] mod_hfs_apple: Allowing access with matching directory. filename = /Library/WebServer/Documents/osm_tiles

To fix this problem simply went in /etc/apache2/httpd.conf and comment the following line:
LoadModule hfs_apple_module libexec/apache2/mod_hfs_apple.so

This hack is not very satisfactory to me, the goal would be to correct mod_tile. The part that looks to need a fix lies in mod_tile.c:1643:

static void register_hooks(__attribute__((unused)) apr_pool_t *p)
{
   ...
   ap_hook_translate_name(tile_translate, NULL, NULL, APR_HOOK_MIDDLE);
   ...
}

For now I don't have the courage to find a real solution, just having a quick look I found this strange line that may cause a problem to anyone (eg., mod_hfs_apple) trying to read the request. In mod_tile.c:1278:

static int tile_translate(request_rec *r)
{
   ...
               r->filename = NULL; 
   ...
}

Thanks for your help @SomeoneElseOSM !!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants