search

derhuerst / hafas-monitor-trips

Using a HAFAS endpoint, watch all trips in a bounding box.
https://github.com/derhuerst/hafas-monitor-trips#hafas-monitor-trips
ISC License
8 stars 0 forks source link

Observation/Question: What the heck is happening with the bounding box? #12

Closed dancesWithCycles closed 9 months ago

dancesWithCycles commented 9 months ago

Hi folks, I am calling this instruction set.

npm i
npm run build
./start

This is the response.

$ export BBOX='{"north": 54.52, "west": 6.54, "south": 51.29, "east": 6.65}'
$ echo $BBOX
{"north": 54.52, "west": 6.54, "south": 51.29, "east": 6.65}
$ ./start.sh
{"level":30,"time":1707769699513,"pid":2319214,"name":"serve","msg":"listening on port 3000"}
...
{"level":30,"time":1707769699783,"pid":2319212,"name":"monitor","msg":"serving Prometheus metrics on port 9323"}
bbox: {"north":53.0665,"west":6.5895,"south":52.7435,"east":6.6005}
bbox: {"north":53.228,"west":6.584,"south":52.582,"east":6.606}
bbox: {"north":53.551,"west":6.573,"south":52.259,"east":6.617}
bbox: {"north":54.197,"west":6.551,"south":51.613,"east":6.639}
bbox: {"north":55.489,"west":6.507,"south":50.321,"east":6.683}
bbox: {"north":58.073,"west":6.419,"south":47.737,"east":6.771}
bbox: {"north":63.241,"west":6.243,"south":42.569,"east":6.947}
bbox: {"north":73.577,"west":5.891,"south":32.233,"east":7.299}
{"level":20,"time":1707769700724,"pid":2319213,"name":"match","origTripId":"1|13666|0|86|12022024","isMatched":false,"matchTime":2,"waitTime":1,"msg":"failed to match fresh movement in 2 after 1 waiting"}
...
bbox: {"north":85.751,"west":5.1872,"south":11.561,"east":8.0028}
{"level":20,"time":1707769700837,"pid":2319213,"name":"match","origTripId":"1|66042|0|86|12022024","isMatched":false,"matchTime":0,"waitTime":1,"msg":"failed to match fresh movement in 0 after 1 waiting"}
...
bbox: {"north":44.407,"west":3.7804,"south":-29.783,"east":9.4096}
{"level":20,"time":1707769701001,"pid":2319213,"name":"match","origTripId":"1|66042|0|86|12022024","isMatched":false,"matchTime":2,"waitTime":0,"msg":"failed to match fresh movement in 2 after 0 waiting"}
...
bbox: {"north":-38.281,"west":0.9745,"south":-67.529,"east":12.2155}
bbox: {"north":23.657,"west":-4.5783,"south":82.153,"east":17.7683}
{"level":50,"time":1707769701218,"pid":2319212,"name":"monitor","err":{"type":"Error","message":"north (23.657) must be larger than south (82.153).","stack":"Error: north (23.657) must be larger than south (82.153).\n    at Object.radar (/home/pacs/sib00/users/gtfsr_srv_fp/git/berlin-gtfs-rt-server/node_modules/hafas-client/index.js:604:29)\n    at atomWithCache (/home/pacs/sib00/users/gtfsr_srv_fp/git/berlin-gtfs-rt-server/node_modules/cached-hafas-client/index.js:193:38)\n    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)\n    at async findMaxRadarResults (/home/pacs/sib00/users/gtfsr_srv_fp/git/berlin-gtfs-rt-server/node_modules/hafas-monitor-trips/lib/find-max-radar-results.js:57:21)\n    at async cachedFindMaxRadarResults (/home/pacs/sib00/users/gtfsr_srv_fp/git/berlin-gtfs-rt-server/node_modules/hafas-monitor-trips/lib/find-max-radar-results.js:90:21)"},"msg":"north (23.657) must be larger than south (82.153)."}
...

It looks like the bounding box I exported export BBOX='{"north": 54.52, "west": 6.54, "south": 51.29, "east": 6.65}' is altered until it is not valid anymore.

I added some extra logs to the console for debugging purposes.

$ vi .../git/berlin-gtfs-rt-server/node_modules/hafas-client/index.js

...
        if ('number' !== typeof east) throw new TypeError('east must be a number.')
        if (north <= south) throw new Error('north (' + north + ') must be larger than south (' + south + ').')//TODO  2024-02-12
        if (east <= west) throw new Error('east must be larger than west.')
...

$ vi .../git/berlin-gtfs-rt-server/node_modules/hafas-monitor-trips/lib/find-max-radar-results.js

...
        const t0 = Date.now()
        console.log('bbox: ' + JSON.stringify(bbox));//TODO begerad 2024-02-12
        const movements = await hafas.radar(bbox, {
...

However, I do not observe this behavior when I am using the bounding box from the readme.

...
$ export BBOX='{"north": 52.52, "west": 13.36, "south": 52.5, "east": 13.39}'
$ echo $BBOX
{"north": 52.52, "west": 13.36, "south": 52.5, "east": 13.39}
sib00-gtfsr_srv_fp@h48:~/git/berlin-gtfs-rt-server$ ./start.sh
{"level":30,"time":1707770463521,"pid":2323054,"name":"monitor","msg":"serving Prometheus metrics on port 9323"}
{"level":30,"time":1707770463527,"pid":2323056,"name":"serve","msg":"listening on port 3000"}
{"level":30,"time":1707770463528,"pid":2323056,"name":"serve","msg":"serving Prometheus metrics on port 9325"}
{"level":30,"time":1707770463546,"pid":2323055,"name":"match","msg":"serving Prometheus metrics on port 9324"}
{"level":20,"time":1707770463918,"pid":2323055,"name":"match","origTripId":"1|46423|22|86|12022024","isMatched":false,"matchTime":2,"waitTime":1,"msg":"failed
...

Any idea what causes this observation?

Cheers!

derhuerst commented 9 months ago

This is likely a bug in hafas-monitor-trips, a transitive dependency of berlin-gtfs-rt-server, specifically in find-max-radar-results.js. Can you run it again with DEBUG='hafas-monitor-trips:find-max-radar-results'?

dancesWithCycles commented 9 months ago

At the moment I can not reproduce the original behavior causing this issue.

export BBOX='{"north": 54.0, "west": 6.54, "south": 51.29, "east": 6.65}'
DEBUG='hafas-monitor-trips:find-max-radar-results' ./start.sh
{"level":30,"time":1707914875192,"pid":193085,"name":"serve","msg":"listening on port 3000"}
{"level":30,"time":1707914875193,"pid":193085,"name":"serve","msg":"serving Prometheus metrics on port 9325"}
{"level":30,"time":1707914875430,"pid":193084,"name":"match","msg":"serving Prometheus metrics on port 9324"}
{"level":30,"time":1707914875554,"pid":193083,"name":"monitor","msg":"serving Prometheus metrics on port 9323"}
  hafas-monitor-trips:find-max-radar-results using maxResults from Redis cache 1000 +0ms
dancesWithCycles commented 9 months ago

Hi!

A couple of days later, same setup, though I did not call

npm i
npm run build

again, just this instruction.

DEBUG='hafas-monitor-trips:find-max-radar-results' ./start.sh

Out of all those log entries I fished these.

./start.sh
{"level":30,"time":1708087988816,"pid":1054036,"name":"serve","msg":"listening on port 3000"}
{"level":30,"time":1708087988820,"pid":1054036,"name":"serve","msg":"serving Prometheus metrics on port 9325"}
{"level":30,"time":1708087988878,"pid":1054035,"name":"match","msg":"serving Prometheus metrics on port 9324"}
{"level":30,"time":1708087988976,"pid":1054034,"name":"monitor","msg":"serving Prometheus metrics on port 9323"}
  hafas-monitor-trips:find-max-radar-results initial bbox { north: 54, west: 6.54, south: 51.29, east: 6.65 } +0ms
  hafas-monitor-trips:find-max-radar-results center [ 6.595000000000001, 52.644999999999996 ] width 7.421457968665957 height 301.3386674328743 +4ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 0 bbox { north: 52.7805, west: 6.5895, south: 52.5095, east: 6.6005 } +0ms
  hafas-monitor-trips:find-max-radar-results 0 results +382ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 1 bbox { north: 52.916, west: 6.584, south: 52.374, east: 6.606 } +1ms
  hafas-monitor-trips:find-max-radar-results 0 results +244ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 2 bbox { north: 53.187, west: 6.573, south: 52.103, east: 6.617 } +1ms
  hafas-monitor-trips:find-max-radar-results 0 results +243ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 3 bbox { north: 53.729, west: 6.551, south: 51.561, east: 6.639 } +1ms
  hafas-monitor-trips:find-max-radar-results 19 results +295ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 4 bbox { north: 54.813, west: 6.507, south: 50.477, east: 6.683 } +0ms
{"level":20,"time":1708087990162,"pid":1054035,"name":"match","origTripId":"1|335879|0|80|16022024","isMatched":false,"matchTime":2,"waitTime":2,"msg":"failed
...
{"level":20,"time":1708087774089,"pid":1052669,"name":"match","origTripId":"1|344768|0|80|16022024","isMatched":false,"matchTime":70,"waitTime":7,"msg":"failed to match fresh movement in 70 after 7 waiting"}
  hafas-monitor-trips:find-max-radar-results 1000 results +6s
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 10 bbox { north: -11.397, west: 0.9744, south: -86.107, east: 12.2156 } +0ms
{"level":20,"time":1708087774093,"pid":1052669,"name":"match","origTripId":"1|344512|0|80|16022024","isMatched":false,"matchTime":3,"waitTime":11,"msg":"faile
...
{"level":20,"time":1708087775185,"pid":1052669,"name":"match","origTripId":"1|332817|0|80|16022024","isMatched":false,"matchTime":18,"waitTime":4,"msg":"failed to match fresh movement in 18 after 4 waiting"}
  hafas-monitor-trips:find-max-radar-results 0 results +1s
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 11 bbox { north: -29.851, west: -4.5789, south: 44.859, east: 17.7689 } +1ms
{"level":50,"time":1708087775192,"pid":1052668,"name":"monitor","err":{"type":"Error","message":"north must be larger than south.","stack":"Error: north must be larger than south.\n    at Object.radar (/home/pacs/sib00/users/gtfsr_srv_fp/git/fp-gtfs-rt-server/node_modules/hafas-client/index.js:604:29)\n    at atomWithCache (/home/pacs/sib00/users/gtfsr_srv_fp/git/fp-gtfs-rt-server/node_modules/cached-hafas-client/index.js:193:38)\n    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)\n    at async findMaxRadarResults (/home/pacs/sib00/users/gtfsr_srv_fp/git/fp-gtfs-rt-server/node_modules/hafas-monitor-trips/lib/find-max-radar-results.js:56:21)\n    at async cachedFindMaxRadarResults (/home/pacs/sib00/users/gtfsr_srv_fp/git/fp-gtfs-rt-server/node_modules/hafas-monitor-trips/lib/find-max-radar-results.js:89:21)"},"msg":"north must be larger than south."}
{"level":20,"time":1708087775196,"pid":1052669,"name":"match","origTripId":"1|332751|0|80|16022024","isMatched":false,"matchTime":18,"waitTime":9,"msg":"failed to match fresh movement in 18 after 9 waiting"}
dancesWithCycles commented 9 months ago

Even turning Redis off and on again does not help.

...
{"level":20,"time":1708088187006,"pid":1055308,"name":"match","origTripId":"1|328524|2|80|16022024","isMatched":false,"matchTime":19,"waitTime":12,"msg":"failed to match fresh movement in 19 after 12 waiting"}
  hafas-monitor-trips:find-max-radar-results 0 results +297ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 11 bbox { north: -29.851, west: -4.5789, south: 44.859, east: 17.7689 } +0ms
{"level":50,"time":1708088187010,"pid":1055307,"name":"monitor","err":{"type":"Error","message":"north must be larger than south.","stack":"Error: north must 
...
dancesWithCycles commented 9 months ago

Even turning NATS streaming server and Redisoff and on again does not help.

...
{"level":20,"time":1708088468201,"pid":1057396,"name":"match","origTripId":"1|328065|0|80|16022024","isMatched":false,"matchTime":41,"waitTime":22,"msg":"failed to match fresh movement in 41 after 22 waiting"}
  hafas-monitor-trips:find-max-radar-results 0 results +350ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 11 bbox { north: -29.851, west: -4.5789, south: 44.859, east: 17.7689 } +1ms
{"level":50,"time":1708088468206,"pid":1057395,"name":"monitor","err":{"type":"Error","message":"north must be larger than south.","stack":"Error: north must be larger than south.\n    at Object.radar (/home/pacs/sib00/users/gtfsr_srv_fp/git/fp-gtfs-rt-server/node_modules/hafas-client/index.js:604:29)\n    at atomWithCache (/home/pacs/sib00/users/gtfsr_srv_fp/git/fp-gtfs-rt-server/node_modules/cached-hafas-client/index.js:193:38)\n    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)\n    at async findMaxRadarResults (/home/pacs/sib00/users/gtfsr_srv_fp/git/fp-gtfs-rt-server/node_modules/hafas-monitor-trips/lib/find-max-radar-results.js:56:21)\n    at async cachedFindMaxRadarResults (/home/pacs/sib00/users/gtfsr_srv_fp/git/fp-gtfs-rt-server/node_modules/hafas-monitor-trips/lib/find-max-radar-results.js:89:21)"},"msg":"north must be larger than south."}
{"level":20,"time":1708088468221,"pid":1057396,"name":"match","origTripId":"1|327819|6|80|16022024","isMatched":false,"matchTime":20,"waitTime":24,"msg":"fail
...
derhuerst commented 9 months ago

At the moment I can not reproduce the original behavior causing this issue.

[…]
  hafas-monitor-trips:find-max-radar-results using maxResults from Redis cache 1000 +0ms

This is likely because an earlier run has succeeded and the maximum number of radar() results supported by the HAFAS endpoint has been cached in Redis.

derhuerst commented 9 months ago

Even turning Redis off and on again does not help.

Even turning NATS streaming server and Redisoff and on again does not help.

Both Redis and NATS streaming server persist their state to disk, so that restarting shouldn't have an effect; Refer to their manuals for how to purge the stored data. For Redis, this is redis-cli -n <db_nr> flushdb (the db nr. depends on how you configured berlin-gtfs-rt-server/hafas-gtfs-rt-feed/hafas-monitor-trips).

derhuerst commented 9 months ago

Which HAFAS endpoint did you run get the error with? The ebb one configured in berlin-gtfs-rt-server, or a different one?

dancesWithCycles commented 9 months ago

VBN

You'll find my experiment/study in this Fahrplaner branch.

derhuerst commented 9 months ago

I managed to reproduce the error! Although not with the same succession of bounding boxes. 🤔

git clone git@github.com:derhuerst/hafas-monitor-trips.git
cd hafas-monitor-trips
git checkout 6.3.0
npm install
# modify example.js to use the VBN HAFAS & remove trip fetching
# …
export BBOX='{"north": 54.52, "west": 6.54, "south": 51.29, "east": 6.65}'
export DEBUG='hafas-monitor-trips*'
redis-cli flushall # purge data from Redis
node example.js
  hafas-monitor-trips starting monitor +0ms
  hafas-monitor-trips:find-max-radar-results initial bbox { north: 54.52, west: 6.54, south: 51.29, east: 6.65 } +0ms
  hafas-monitor-trips:find-max-radar-results center [ 6.595000000000001, 52.905 ] width 7.377261578497659 height 359.16010915431167 +1ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 0 bbox { north: 53.0665, west: 6.5895, south: 52.7435, east: 6.6005 } +0ms
  hafas-monitor-trips:find-max-radar-results 0 results +445ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 1 bbox { north: 53.228, west: 6.584, south: 52.582, east: 6.606 } +1ms
  hafas-monitor-trips:find-max-radar-results 0 results +211ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 2 bbox { north: 53.551, west: 6.573, south: 52.259, east: 6.617 } +0ms
  hafas-monitor-trips:find-max-radar-results 0 results +209ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 3 bbox { north: 54.197, west: 6.551, south: 51.613, east: 6.639 } +0ms
movement 1|340399|0|80|19022024 Bus C1 pos 51.856324 6.630309
movement 1|340347|1|80|19022024 Bus C4 pos 51.818767 6.627019
[…]
movement 1|285484|0|80|19022024 RE19 pos 51.641842 6.636538
movement 1|54546|9|80|19022024 Bus S75 pos 51.834112 6.619486
  hafas-monitor-trips:find-max-radar-results 18 results +2s
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 4 bbox { north: 55.489, west: 6.507, south: 50.321, east: 6.683 } +0ms
movement 1|293042|11|80|19022024 RE10 pos 51.325404 6.611234
movement 1|293027|10|80|19022024 RE10 pos 51.329152 6.604186
[…]
movement 1|54546|9|80|19022024 Bus S75 pos 51.833995 6.61945
movement 1|54094|0|80|19022024 Bus C8 pos 51.881737 6.659344
  hafas-monitor-trips:find-max-radar-results 46 results +425ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 5 bbox { north: 58.073, west: 6.419, south: 47.737, east: 6.771 } +0ms
movement 1|293216|11|80|19022024 RE44 pos 51.408536 6.73524
movement 1|293042|11|80|19022024 RE10 pos 51.325404 6.611234
[…]
movement 1|54094|0|80|19022024 Bus C8 pos 51.881737 6.659344
movement 1|53982|0|80|19022024 Bus 752 pos 51.764949 6.730493
  hafas-monitor-trips:find-max-radar-results 86 results +554ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 6 bbox { north: 63.241, west: 6.243, south: 42.569, east: 6.947 } +0ms
movement 1|293228|10|80|19022024 RE44 pos 51.429786 6.775907
movement 1|293216|11|80|19022024 RE44 pos 51.408635 6.735437
[…]
movement 1|10449|10|80|19022024 Bus 10 pos 52.494505 6.872307
movement 1|10435|7|80|19022024 Bus 10 pos 52.493902 6.8794
  hafas-monitor-trips:find-max-radar-results 169 results +772ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 7 bbox { north: 73.577, west: 5.891, south: 32.233, east: 7.299 } +0ms
movement 1|349452|0|80|19022024 Bus 965 pos 53.058623 7.272768
movement 1|347706|0|80|19022024 Bus 929 pos 52.643357 7.077819
[…]
movement 1|9402|0|80|19022024 Bus 952 pos 52.866829 7.184997
movement 1|9083|3|80|19022024 Bus 933 pos 52.692357 7.287492
  hafas-monitor-trips:find-max-radar-results 400 results +1s
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 8 bbox { north: 85.751, west: 5.1872, south: 11.561, east: 8.0028 } +0ms
movement 1|349881|0|80|19022024 RE2 pos 52.090601 7.840131
movement 1|349855|0|80|19022024 Bus 605 pos 53.223305 7.434457
[…]
movement 1|426|0|80|19022024 Bus 620 pos 52.427948 7.972785
movement 1|313|1|80|19022024 Bus X610 pos 52.481434 7.817208
  hafas-monitor-trips:find-max-radar-results 803 results +3s
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 9 bbox { north: 44.407, west: 3.7804, south: -29.783, east: 9.4096 } +0ms
  hafas-monitor-trips:find-max-radar-results 0 results +490ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 10 bbox { north: -38.281, west: 0.9745, south: -67.529, east: 12.2155 } +1ms
  hafas-monitor-trips:find-max-radar-results 0 results +212ms
  hafas-monitor-trips:find-max-radar-results calling radar() iteration 11 bbox { north: 23.657, west: -4.5783, south: 82.153, east: 17.7683 } +0ms
Error: north must be larger than south.
    at Object.radar (/Users/j/web/hafas-monitor-trips/node_modules/hafas-client/index.js:604:29)
    at findMaxRadarResults (/Users/j/web/hafas-monitor-trips/lib/find-max-radar-results.js:56:33)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async cachedFindMaxRadarResults (/Users/j/web/hafas-monitor-trips/lib/find-max-radar-results.js:89:21)
derhuerst commented 9 months ago

Although the bounding box you defined is very unusual (a 7x360km north-south strip, from somewhere in the North Sea to Düsseldorf, through Netherlands), it should definitely work.

dancesWithCycles commented 9 months ago

That is about the area the Fahrplaner is serving. It includes areas in HB, NI, HH, SH and MV.

derhuerst commented 9 months ago

Are you sure?

Screenshot 2024-02-21 at 22 03 40
dancesWithCycles commented 9 months ago

That is a classic typo!

This helpful website provides the bounding box for the Fahrplaner in CSV format with the following values.

6.35,51.29,12.93,54.27

Those values translated into the readme format shall look like this.

export BBOX='{"north": 54.27, "west": 6.35, "south": 51.29, "east": 12.93}'

I obviously got confused with the east value. ;-)

Cheers for making me aware of my confusion!

derhuerst commented 9 months ago

While hafas-monitor-trips's current bounding box calculation logic computes ridiculously large bounding boxes with your example input, the actual problem was that hafas-client assumed & asserted that bbox.north <= bbox.south.

I have fixed this in https://github.com/public-transport/hafas-client/commit/90b114040163e13a69840707818985fec81e9a39 and published the fix as hafas-client@6.2.2, so an npm upgrade should make the error message disappear @dancesWithCycles.