freemap-mapnik-ondemand crash : TypeError [ERR_UNKNOWN_ENCODING]: Unknown encoding: buffer

[necarnot]

After the start of the freemap-mapnik-ondemand service, it is crashing with the following error :

déc. 31 14:36:40 freemap node[418623]: HTTP server listening.
déc. 31 14:37:04 freemap node[418623]: Rendering tile 10/568/351: rendering [ 'doesntExist' ]
déc. 31 14:37:04 freemap node[418623]: Rendering tile 10/569/351: rendering [ 'doesntExist' ]
déc. 31 14:37:04 freemap node[418623]: Rendering tile 10/568/350: rendering [ 'doesntExist' ]
déc. 31 14:37:04 freemap node[418623]: Rendering tile 10/569/350: rendering [ 'doesntExist' ]
déc. 31 14:37:04 freemap node[418623]: Rendering tile 10/568/352: rendering [ 'doesntExist' ]
déc. 31 14:37:04 freemap node[418623]: Rendering tile 10/569/352: rendering [ 'doesntExist' ]
déc. 31 14:37:09 freemap node[418623]: node:buffer:820
déc. 31 14:37:09 freemap node[418623]:     throw new ERR_UNKNOWN_ENCODING(encoding);
déc. 31 14:37:09 freemap node[418623]:     ^
déc. 31 14:37:09 freemap node[418623]: TypeError [ERR_UNKNOWN_ENCODING]: Unknown encoding: buffer
déc. 31 14:37:09 freemap node[418623]:     at new NodeError (node:internal/errors:400:5)
déc. 31 14:37:09 freemap node[418623]:     at Buffer.toString (node:buffer:820:11)
déc. 31 14:37:09 freemap node[418623]:     at joinChunks (/data/freemap-mapnik/node_modules/promisify-child-process/index.cjs:25:33)
déc. 31 14:37:09 freemap node[418623]:     at defineOutputs (/data/freemap-mapnik/node_modules/promisify-child-process/index.cjs:82:24)
déc. 31 14:37:09 freemap node[418623]:     at ChildProcess.done (/data/freemap-mapnik/node_modules/promisify-child-process/index.cjs:108:9)
déc. 31 14:37:09 freemap node[418623]:     at ChildProcess.emit (node:events:513:28)
déc. 31 14:37:09 freemap node[418623]:     at maybeClose (node:internal/child_process:1091:16)
déc. 31 14:37:09 freemap node[418623]:     at Socket.<anonymous> (node:internal/child_process:449:11)
déc. 31 14:37:09 freemap node[418623]:     at Socket.emit (node:events:513:28)
déc. 31 14:37:09 freemap node[418623]:     at Pipe.<anonymous> (node:net:321:12) {
déc. 31 14:37:09 freemap node[418623]:   code: 'ERR_UNKNOWN_ENCODING'
déc. 31 14:37:09 freemap node[418623]: }
déc. 31 14:37:09 freemap node[418623]: Node.js v18.13.0
déc. 31 14:37:09 freemap systemd[1]: freemap-mapnik-ondemand.service: Main process exited, code=exited, status=1/FAILURE

I'm not a coder, so I tried to search for explanations about this but I don't even know if the problem is coming from the freemap-mapnik code or from a sub project called by freemap-mapnik.

[necarnot]

Reading this (https://www.npmjs.com/package/promisify-child-process), I see the following comment :

Upgrading to v3

You must now pass maxBuffer or encoding to spawn/fork if you want to capture stdout or stderr.

Here are the versions of my various components :

node JS : v18.13.0
$ npm ls
freemap-mapnik@1.0.0 /data/freemap-mapnik
├── @types/color-convert@2.0.3
├── @types/config@3.3.3
├── @types/node@20.10.4
├── color-convert@2.0.1
├── concurrently@8.2.2
├── config@3.3.9
├── eslint@8.55.0
├── freemap-mapserver@0.0.6 (git+ssh://git@github.com/FreemapSlovakia/freemap-mapserver.git#70868ffb25230d7873065b25bd7344eecde4bff3)
├── jsxnik@0.0.14
├── nodemon@3.0.2
└── typescript@5.3.3
$ head -3 node_modules/promisify-child-process/package.json 
{
  "name": "promisify-child-process",
  "version": "4.1.1",

So maybe I was wondering if some components were too recent according to the code?

[necarnot]

According to what I've read, the issue is coming from the freemap-mapserver module, in lib/renderer.js, line 252 :
https://github.com/FreemapSlovakia/freemap-mapserver/blob/f1886d553c702761914e07f280e50fa16a164073/lib/renderrer.js#L252

It seems that encoding: 'buffer' is not accepted as it was with the child_process module.
Though, when trying to replace it by encoding: 'utf8' (as suggested here https://www.npmjs.com/package/promisify-child-process#capturing-output), the encoding error disappears, but I'm still getting the following looping errors (and no tiles produced) :

janv. 02 17:25:16 freemap node[2561217]: HTTP server listening.                                                                                                                                                                            
janv. 02 17:25:23 freemap node[2561217]: Rendering tile 10/568/351: rendering [ 'doesntExist' ]                                                                                                                                            
janv. 02 17:25:23 freemap node[2561217]: Rendering tile 10/569/351: rendering [ 'doesntExist' ]                                                                                                                                            
janv. 02 17:25:23 freemap node[2561217]: Rendering tile 10/568/350: rendering [ 'doesntExist' ]                                                                                                                                            
janv. 02 17:25:23 freemap node[2561217]: Rendering tile 10/569/350: rendering [ 'doesntExist' ]                                                                                                                                            
janv. 02 17:25:23 freemap node[2561217]: Rendering tile 10/568/352: rendering [ 'doesntExist' ]                                                                                                                                            
janv. 02 17:25:23 freemap node[2561217]: Rendering tile 10/569/352: rendering [ 'doesntExist' ]                                                                                                                                            
janv. 02 17:25:27 freemap node[2561217]:   Error: Process exited with code 25                                                                                                                                                              
janv. 02 17:25:27 freemap node[2561217]:       at ChildProcess.done (/data/freemap-mapnik/node_modules/promisify-child-process/index.cjs:70:19)                                                                                            
janv. 02 17:25:27 freemap node[2561217]:       at ChildProcess.emit (node:events:513:28)                                                                                                                                                   
janv. 02 17:25:27 freemap node[2561217]:       at maybeClose (node:internal/child_process:1091:16)
janv. 02 17:25:27 freemap node[2561217]:       at Socket.<anonymous> (node:internal/child_process:449:11)
janv. 02 17:25:27 freemap node[2561217]:       at Socket.emit (node:events:513:28)
janv. 02 17:25:27 freemap node[2561217]:       at Pipe.<anonymous> (node:net:321:12)

At this point, I don't know how to debug further.
(Is it normal to read 'doesntExist' in the Rendering tile log line?)

[zdila]

Do you have pngquant installed on your system? If not then set pngquantOptions: null in your config file.

[necarnot]

Hi Martin,

pngquant was not installed on my system, so I installed it:

apt show pngquant 
Package: pngquant
Version: 2.17.0-1
Priority: optional
Section: graphics
Maintainer: Debian PhotoTools Maintainers <pkg-phototools-devel@lists.alioth.debian.org>
Installed-Size: 62,5 kB
Depends: libc6 (>= 2.34), libimagequant0 (>= 2.11.10), libpng16-16 (>= 1.6.2-1)

but after restarting the freemap-mapnik-ondemand service, the exact same error is showing, which I guess is expected, as the error seems to come from the fact that "buffer" is not an accepted encoding option is the use of the promisify module.

[zdila]

Does it work if you set pngquantOptions: null in your config file?

[necarnot]

Hello Martin,

Well, now, I've set pngquantOptions: null in config/ondemand.json5
Now I don't get any TypeError errors, so we're progressing.

Now, when running only the freemap-mapnik-ondemand service, and launching the preview.html file in a browser, I can see that the queries are sent, and understood by the daemon.

My hardware is limited so I did only imported the Europe/Andorra pbf file from Geofabrik. So when doing my tests, I'm zooming out in the hope that some relevant tiles (of the imported zone) will be produced.

And indeed, I see that some tiles are produced, but they are all white blank.
To be more precise, some are showing only letters (please look at the provided screenshot) and the logs are showing these errors :

janv. 10 14:48:29 freemap node[69106]: Rendering tile 12/2272/1405: rendering [ 'doesntExist' ]                                                                                                                                    
janv. 10 14:48:29 freemap node[69106]: Measurement: [                                                                                                                                                                              
janv. 10 14:48:29 freemap node[69106]:   'encode: 43x 2.441860465116279',                                                                                                                                                          
janv. 10 14:48:29 freemap node[69106]:   'render: 43x 383.30232558139534',                                                                                                                                                         
janv. 10 14:48:29 freemap node[69106]:   'write: 43x 45.627906976744185'                                                                                                                                                           
janv. 10 14:48:29 freemap node[69106]: ]                                                                                                                                                                                           
janv. 10 14:48:29 freemap node[69106]: Rendering tile 12/2278/1405: rendering [ 'doesntExist' ]                                                                                                                                    
janv. 10 14:48:36 freemap node[69106]: Rendering tile 12/2275/1404: rendering [ 'doesntExist' ]                                                                                                                                    
janv. 10 14:48:36 freemap node[69106]: Rendering tile 12/2276/1404: rendering [ 'doesntExist' ]                                                                                                                                    
janv. 10 14:48:36 freemap node[69106]: Rendering tile 12/2277/1404: rendering [ 'doesntExist' ]                                                                                                                                    
janv. 10 14:48:36 freemap node[69106]: Rendering tile 12/2274/1404: rendering [ 'doesntExist' ]                                                                                                                                    
janv. 10 14:48:36 freemap node[69106]: Rendering tile 12/2273/1404: rendering [ 'doesntExist' ]                                                                                                                                    
janv. 10 14:48:36 freemap node[69106]: Rendering tile 12/2278/1404: rendering [ 'doesntExist' ]                                                                                                                                    
janv. 10 14:48:46 freemap node[69106]: Rendering tile 10/572/352: rendering [ 'doesntExist' ]                                                                                                                                      
janv. 10 14:48:47 freemap node[69106]: Rendering tile 6/35/21: rendering [ 'doesntExist' ]                                                                                                                                         
janv. 10 14:48:47 freemap node[69106]: Rendering tile 6/35/22: rendering [ 'doesntExist' ]                                                                                                                                         
janv. 10 14:48:47 freemap node[69106]: Rendering tile 6/36/21: rendering [ 'doesntExist' ]                                                                                                                                         
janv. 10 14:48:47 freemap node[69106]: Rendering tile 6/36/22: rendering [ 'doesntExist' ]                                                                                                                                         
janv. 10 14:48:47 freemap node[69106]: Rendering tile 6/34/21: rendering [ 'doesntExist' ]                                                                                                                                         
janv. 10 14:48:47 freemap node[69106]: Rendering tile 6/37/21: rendering [ 'doesntExist' ]                                                                                                                                         
janv. 10 14:48:47 freemap node[69106]:   Error: PostGIS: geometry name lookup failed for table '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. Please manually provide the 'geometry_field' parameter or ad
d an entry in the geometry_columns for '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'.                                                                                                                     
janv. 10 14:48:47 freemap node[69106]:   Error: PostGIS: geometry name lookup failed for table '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. Please manually provide the 'geometry_field' parameter or ad
d an entry in the geometry_columns for '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'.                                                                                                                     
janv. 10 14:48:47 freemap node[69106]:   Error: PostGIS: geometry name lookup failed for table '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. Please manually provide the 'geometry_field' parameter or ad
d an entry in the geometry_columns for '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'.                                                                                                                     
janv. 10 14:48:47 freemap node[69106]:   Error: PostGIS: geometry name lookup failed for table '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. Please manually provide the 'geometry_field' parameter or ad
d an entry in the geometry_columns for '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'.                                                                                                                     
janv. 10 14:48:47 freemap node[69106]:   Error: PostGIS: geometry name lookup failed for table '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. Please manually provide the 'geometry_field' parameter or ad
d an entry in the geometry_columns for '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'.                                                                                                                     
janv. 10 14:48:47 freemap node[69106]:   Error: PostGIS: geometry name lookup failed for table '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. Please manually provide the 'geometry_field' parameter or ad
d an entry in the geometry_columns for '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'.                                                                        
...

This was when I was running the ondemand service only, and looking at the results via journalctl -xef .

Since then, I tried to stop it, then run it via UV_THREADPOOL_SIZE=32 npm run watch and what I'm witnessing since an hour is the pre-rendering of tons of tiles, which I guess is caused by the fact that today I forgot to update the osm timestamp and the service may consider every tile as dirty (? <- I'm writing that as if I was understanding a mere word, but it's not the case)

Anyway, I'm going to let the pre-render finish its task in the hope that once finished, the on-demand service will start to reply to the browser queries and we'll see.
But so far, I 'm expecting the on-demand service to give the same errors as mentioned above.

In any case, here is a screenshot of the preview.html, in systemd mode :

[zdila]

hi nec turn off prerendering in config (prerender: null) regarding errors - pull fresh changes from github.

…

On Wed, Jan 10, 2024 at 3:34 PM necarnot ***@***.***> wrote: Hello Martin, Well, now, I've set pngquantOptions: null in config/ondemand.json5 Now I don't get any TypeError errors, so we're progressing. Now, when running only the freemap-mapnik-ondemand service, and launching the preview.html file in a browser, I can see that the queries are sent, and understood by the daemon. My hardware is limited so I did only imported the Europe/Andorra pbf file from Geofabrik. So when doing my tests, I'm zooming *out* in the hope that some relevant tiles (of the imported zone) will be produced. And indeed, I see that some tiles are produced, but they are all white blank. To be more precise, some are showing only letters (please look at the provided screenshot) and the logs are showing these errors : janv. 10 14:48:29 freemap node[69106]: Rendering tile 12/2272/1405: rendering [ 'doesntExist' ] janv. 10 14:48:29 freemap node[69106]: Measurement: [ janv. 10 14:48:29 freemap node[69106]: 'encode: 43x 2.441860465116279', janv. 10 14:48:29 freemap node[69106]: 'render: 43x 383.30232558139534', janv. 10 14:48:29 freemap node[69106]: 'write: 43x 45.627906976744185' janv. 10 14:48:29 freemap node[69106]: ] janv. 10 14:48:29 freemap node[69106]: Rendering tile 12/2278/1405: rendering [ 'doesntExist' ] janv. 10 14:48:36 freemap node[69106]: Rendering tile 12/2275/1404: rendering [ 'doesntExist' ] janv. 10 14:48:36 freemap node[69106]: Rendering tile 12/2276/1404: rendering [ 'doesntExist' ] janv. 10 14:48:36 freemap node[69106]: Rendering tile 12/2277/1404: rendering [ 'doesntExist' ] janv. 10 14:48:36 freemap node[69106]: Rendering tile 12/2274/1404: rendering [ 'doesntExist' ] janv. 10 14:48:36 freemap node[69106]: Rendering tile 12/2273/1404: rendering [ 'doesntExist' ] janv. 10 14:48:36 freemap node[69106]: Rendering tile 12/2278/1404: rendering [ 'doesntExist' ] janv. 10 14:48:46 freemap node[69106]: Rendering tile 10/572/352: rendering [ 'doesntExist' ] janv. 10 14:48:47 freemap node[69106]: Rendering tile 6/35/21: rendering [ 'doesntExist' ] janv. 10 14:48:47 freemap node[69106]: Rendering tile 6/35/22: rendering [ 'doesntExist' ] janv. 10 14:48:47 freemap node[69106]: Rendering tile 6/36/21: rendering [ 'doesntExist' ] janv. 10 14:48:47 freemap node[69106]: Rendering tile 6/36/22: rendering [ 'doesntExist' ] janv. 10 14:48:47 freemap node[69106]: Rendering tile 6/34/21: rendering [ 'doesntExist' ] janv. 10 14:48:47 freemap node[69106]: Rendering tile 6/37/21: rendering [ 'doesntExist' ] janv. 10 14:48:47 freemap node[69106]: Error: PostGIS: geometry name lookup failed for table '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. Please manually provide the 'geometry_field' parameter or ad d an entry in the geometry_columns for '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. janv. 10 14:48:47 freemap node[69106]: Error: PostGIS: geometry name lookup failed for table '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. Please manually provide the 'geometry_field' parameter or ad d an entry in the geometry_columns for '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. janv. 10 14:48:47 freemap node[69106]: Error: PostGIS: geometry name lookup failed for table '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. Please manually provide the 'geometry_field' parameter or ad d an entry in the geometry_columns for '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. janv. 10 14:48:47 freemap node[69106]: Error: PostGIS: geometry name lookup failed for table '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. Please manually provide the 'geometry_field' parameter or ad d an entry in the geometry_columns for '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. janv. 10 14:48:47 freemap node[69106]: Error: PostGIS: geometry name lookup failed for table '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. Please manually provide the 'geometry_field' parameter or ad d an entry in the geometry_columns for '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. janv. 10 14:48:47 freemap node[69106]: Error: PostGIS: geometry name lookup failed for table '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. Please manually provide the 'geometry_field' parameter or ad d an entry in the geometry_columns for '(SELECT ST_SetSRID(ST_MakePoint(0, 0), 3857) AS geom LIMIT 0) AS foo'. ... This was when I was running the ondemand service only, and looking at the results via journalctl -xef . Since then, I tried to stop it, then run it via UV_THREADPOOL_SIZE=32 npm run watch and what I'm witnessing since an hour is the pre-rendering of tons of tiles, which I guess is caused by the fact that today I forgot to update the osm timestamp and the service may consider every tile as dirty (? <- I'm writing that as if I was understanding a mere word, but it's not the case) Anyway, I'm going to let the pre-render finish its task in the hope that once finished, the on-demand service will start to reply to the browser queries and we'll see. But so far, I 'm expecting the on-demand service to give the same errors as mentioned above. In any case, here is a screenshot of the preview.html, in systemd mode : 2024-01-10_15-17.png (view on web) <https://github.com/FreemapSlovakia/freemap-mapnik/assets/4737235/c2dd89fb-1269-4b9e-9514-a801e223c18a> — Reply to this email directly, view it on GitHub <#317 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAE3JP4GGUOHAEH7HB67JWDYN2RJFAVCNFSM6AAAAABBKFKDF2VHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTQOBUHE3DKNRXHE> . You are receiving this because you commented.Message ID: ***@***.***>

-- Ing. Martin Ždila <http://www.openstreetmap.org/user/*Martin*> OZ Freemap Slovakia tel:+421-908-363-848 ***@***.*** http://www.freemap.sk/

[necarnot]

Martin,

This [1] makes me happy!
I'm feeling that I'm just on the first step of the ladder of the understanding, but I'd like to salute your patience in helping me so far.

[1]