Bug: Statuspage / Statusbot not displaying clients after long runtime

hbeni commented 9 months ago

Describe the bug

Related problem to #168 appeared again. The statusbot did run for about two weeks, showing an also long running bot client (radio replay).

Sometime, the database was not written to anymore; the file had an days-old timestamp. Couriosly this was not reflected by the web page (which should display not-up-to-date DB).

:eyes: Needs investigation/testing; but is a rare bug. A open question is, if there is some trigger that causes this behaviour?

To Reproduce ??? Keep it running for a undefined long time. Unprobably it is connected to clients joining/leaving?

Expected behavior Regardless of runtime, the statuspage should display the actual status flawlessly.

Workaround Known workaround is to kill and restart the status bot by cron; daily for example.

hbeni commented 9 months ago

Occurred again:

Website reports: Last DB update: 17.02.2024 01:42:05 (UTC) (~3 days ago) Statusbot running since: 2024-02-14 22:10:15 (according to log; still running) DB File timestamp: 2024-02-17 02:42:05.297614019 +0100 Usage timestamp: 20. Feb 17:11 (current!) Radio bot is still operable, so all works nicely - from a radio transmission perspective.

Contents of fgcom-web.db:

{"clients":[{"callsign":"wesnothSAT","updated":1708134122,"lat":"45.0","lon":"-30.0","alt":"10000000","radios":{"0":{"srv":1,"operable":1,"vlt":12,"ptt":"1","frequency":"0.345","power":"10000","pbt":1,"dialedFRQ":"0.345"}},"type":"playback-bot"},{"callsign":"GIA-167","updated":1708134124,"lat":"-6.120713","lon":"106.639481","alt":"9.753718","radios":{"0":{"srv":1,"operable":"1","vlt":12,"ptt":"1","frequency":"910.0000","power":"10.000000","pbt":1,"dialedFRQ":"910.00"}},"type":"client"}],"meta":{"highscore_date":1708134115,"highscore_clients":1}}

"updated":1708134124 is: 2024-02-17 01:42:04 GMT+0000

Contents of fgcom-usage.stats:

...
20240220154915 0 1
20240220155015 0 1
20240220155115 0 1
20240220155215 1 1
20240220155315 1 1
20240220155415 0 1
20240220155515 0 1
20240220155615 0 1
20240220155715 0 1
20240220155815 0 1
...

so still producing correct output; which is also visible in the statuspage.

Log says (here it still worked):

2024-02-14 22:10:20 [DBG] Update db '/home/beni/fgcom-web.db'
2024-02-14 22:10:20 [DBG] opened db '/home/beni/fgcom-web.db.part'
2024-02-14 22:10:20 [DBG] generateOutData(): processing user: 2 with idty=0
2024-02-14 22:10:20 [DBG]   callsign=wesnothSAT (type=playback-bot)
2024-02-14 22:10:20 [DBG]   radio #0, ptt='1', frq='0.345', dialedFRQ='0.345', operable=1
2024-02-14 22:10:20 [DBG]   updated=1707945015
2024-02-14 22:10:20 [DBG]   lat=45.0; lon=-30.0; alt=10000000
2024-02-14 22:10:20 [DBG] JSON RESULT: {"clients":[{"callsign":"wesnothSAT","updated":1707945015,"lat":"45.0","lon":"-30.0","alt":"10000000","radios":{"0":{"srv":1,"operable":1,"vlt":12,"ptt":"1","frequency":"0.345","power":"10000","pbt":1,"dialedFRQ":"0.345"}},"type":"playback-bot"}],"meta":{"highscore_date":0,"highscore_clients":0}}
2024-02-14 22:10:20 [DBG] wrote db '/home/beni/fgcom-web.db.part'
2024-02-14 22:10:20 [DBG] published db '/home/beni/fgcom-web.db'

And now:

2024-02-20 16:23:10 [DBG] Update db '/home/beni/fgcom-web.db'
2024-02-20 16:23:10 [DBG] opened db '/home/beni/fgcom-web.db.part'
2024-02-20 16:23:10 [DBG] generateOutData(): processing user: 2 with idty=0
2024-02-20 16:23:10 [DBG]   callsign=wesnothSAT (type=playback-bot)
2024-02-20 16:23:10 [DBG]   radio #0, ptt='1', frq='0.345', dialedFRQ='0.345', operable=1
2024-02-20 16:23:10 [DBG]   updated=1708442582
2024-02-20 16:23:10 [DBG]   lat=45.0; lon=-30.0; alt=10000000
2024-02-20 16:23:10 [DBG] generateOutData(): processing user: 2 with idty=0
2024-02-20 16:23:10 [DBG]   callsign=wesnothSAT (type=playback-bot)
2024-02-20 16:23:10 [DBG]   radio #0, ptt='1', frq='0.345', dialedFRQ='0.345', operable=1
2024-02-20 16:23:10 [DBG]   updated=1708442582
2024-02-20 16:23:10 [DBG]   lat=45.0; lon=-30.0; alt=10000000
2024-02-20 16:23:10 [DBG] generateOutData(): processing user: 50 with idty=0
2024-02-20 16:23:10 [DBG] User sid=50 not connected anymore!
2024-02-20 16:23:10 [DBG]   callsign=SimConnect (type=client)
2024-02-20 16:23:10 [DBG]   radio #0, ptt='0', frq='SimConnect-COM1', dialedFRQ='SimConnect-COM1', operable=1
2024-02-20 16:23:10 [DBG]   radio #1, ptt='0', frq='SimConnect-COM2', dialedFRQ='SimConnect-COM2', operable=1
2024-02-20 16:23:10 [DBG]   updated=1708216879
2024-02-20 16:23:10 [DBG]   lat=0.000000; lon=0.000000; alt=0.000000
2024-02-20 16:23:10 [DBG] generateOutData(): processing user: 2 with idty=0
2024-02-20 16:23:10 [DBG]   callsign=wesnothSAT (type=playback-bot)
2024-02-20 16:23:10 [DBG]   radio #0, ptt='1', frq='0.345', dialedFRQ='0.345', operable=1
2024-02-20 16:23:10 [DBG]   updated=1708442582
2024-02-20 16:23:10 [DBG]   lat=45.0; lon=-30.0; alt=10000000
2024-02-20 16:23:10 [DBG] generateOutData(): processing user: 50 with idty=0
2024-02-20 16:23:10 [DBG] User sid=50 not connected anymore!
2024-02-20 16:23:10 [DBG]   callsign=SimConnect (type=client)
2024-02-20 16:23:10 [DBG]   radio #0, ptt='0', frq='SimConnect-COM1', dialedFRQ='SimConnect-COM1', operable=1
2024-02-20 16:23:10 [DBG]   radio #1, ptt='0', frq='SimConnect-COM2', dialedFRQ='SimConnect-COM2', operable=1
2024-02-20 16:23:10 [DBG]   updated=1708216879
2024-02-20 16:23:10 [DBG]   lat=0.000000; lon=0.000000; alt=0.000000
2024-02-20 16:23:10 [DBG] generateOutData(): processing user: 2 with idty=0
2024-02-20 16:23:10 [DBG]   callsign=wesnothSAT (type=playback-bot)
2024-02-20 16:23:10 [DBG]   radio #0, ptt='1', frq='0.345', dialedFRQ='0.345', operable=1
2024-02-20 16:23:10 [DBG]   updated=1708442582
2024-02-20 16:23:10 [DBG]   lat=45.0; lon=-30.0; alt=10000000
2024-02-20 16:23:10 [DBG] generateOutData(): processing user: 50 with idty=0
2024-02-20 16:23:10 [DBG] User sid=50 not connected anymore!
2024-02-20 16:23:10 [DBG]   callsign=SimConnect (type=client)
2024-02-20 16:23:10 [DBG]   radio #0, ptt='0', frq='SimConnect-COM1', dialedFRQ='SimConnect-COM1', operable=1
2024-02-20 16:23:10 [DBG]   radio #1, ptt='0', frq='SimConnect-COM2', dialedFRQ='SimConnect-COM2', operable=1
2024-02-20 16:23:10 [DBG]   updated=1708216879
2024-02-20 16:23:10 [DBG]   lat=0.000000; lon=0.000000; alt=0.000000
2024-02-20 16:23:10 [DBG] generateOutData(): processing user: 42 with idty=0
2024-02-20 16:23:10 [DBG] User sid=42 not connected anymore!
2024-02-20 16:23:12 [DBG] DATA INCOMING FROM=2
2024-02-20 16:23:12 [DBG] Received FGCOM-plugin data, dataID='FGCOM:PING', from=[2] 'FGCOM-RADIO-37928'
2024-02-20 16:23:12 [DBG]   data='0'
2024-02-20 16:23:12 [DBG]   datatype='FGCOM'
2024-02-20 16:23:12 [DBG]   packtype='PING'
2024-02-20 16:23:12 [DBG] ping packet for sid=2; iid=0
2024-02-20 16:23:12 [DBG] Parsing done. New remote state:
2024-02-20 16:23:12 [DBG] sid=2; idty=0 callsign:       wesnothSAT
2024-02-20 16:23:12 [DBG] sid=2; idty=0 type:   playback-bot
2024-02-20 16:23:12 [DBG] sid=2; idty=0 lat:    45.0
2024-02-20 16:23:12 [DBG] sid=2; idty=0 lon:    -30.0
2024-02-20 16:23:12 [DBG] sid=2; idty=0 alt:    10000000
2024-02-20 16:23:12 [DBG] sid=2; idty=0    radio #0 frequency='0.345'
2024-02-20 16:23:12 [DBG] sid=2; idty=0    radio #0 dialedFRQ='0.345'
2024-02-20 16:23:12 [DBG] sid=2; idty=0    radio #0       ptt='1'
2024-02-20 16:23:12 [DBG] sid=2; idty=0    radio #0       pwr='10000'
2024-02-20 16:23:12 [DBG] sid=2; idty=0    radio #0       opr='1'
2024-02-20 16:23:12 [DBG] sid=2; idty=0 lastUpdate:     1708442592

[... some more clients not connected anymore ...]

2024-02-20 16:23:12 [DBG] -----------
2024-02-20 16:23:15 [DBG] Update db '/home/beni/fgcom-web.db'
2024-02-20 16:23:15 [DBG] opened db '/home/beni/fgcom-web.db.part'
2024-02-20 16:23:15 [DBG] generateOutData(): processing user: 2 with idty=0
2024-02-20 16:23:15 [DBG]   callsign=wesnothSAT (type=playback-bot)
2024-02-20 16:23:15 [DBG]   radio #0, ptt='1', frq='0.345', dialedFRQ='0.345', operable=1
[... and the next out cycle starts ...]

The last succesful publish was this:

2024-02-17 02:42:05 [DBG] Update db '/home/beni/fgcom-web.db'
2024-02-17 02:42:05 [DBG] opened db '/home/beni/fgcom-web.db.part'
2024-02-17 02:42:05 [DBG] generateOutData(): processing user: 2 with idty=0
2024-02-17 02:42:05 [DBG]   callsign=wesnothSAT (type=playback-bot)
2024-02-17 02:42:05 [DBG]   radio #0, ptt='1', frq='0.345', dialedFRQ='0.345', operable=1
2024-02-17 02:42:05 [DBG]   updated=1708134122
2024-02-17 02:42:05 [DBG]   lat=45.0; lon=-30.0; alt=10000000
2024-02-17 02:42:05 [DBG] generateOutData(): processing user: 40 with idty=0
2024-02-17 02:42:05 [DBG]   callsign=GIA-167 (type=client)
2024-02-17 02:42:05 [DBG]   radio #0, ptt='1', frq='910.0000', dialedFRQ='910.00', operable=1
2024-02-17 02:42:05 [DBG]   updated=1708134124
2024-02-17 02:42:05 [DBG]   lat=-6.120713; lon=106.639481; alt=9.753718
2024-02-17 02:42:05 [DBG] JSON RESULT: {"clients":[{"callsign":"wesnothSAT","updated":1708134122,"lat":"45.0","lon":"-30.0","alt":"10000000","radios":{"0":{"srv":1,"operable":1,"vlt":12,"ptt":"1","frequency":"0.345","power":"10000","pbt":1,"dialedFRQ":"0.345"}},"type":"playback-bot"},{"callsign":"GIA-167","updated":1708134124,"lat":"-6.120713","lon":"106.639481","alt":"9.753718","radios":{"0":{"srv":1,"operable":"1","vlt":12,"ptt":"1","frequency":"910.0000","power":"10.000000","pbt":1,"dialedFRQ":"910.00"}},"type":"client"}],"meta":{"highscore_date":1708134115,"highscore_clients":1}}
2024-02-17 02:42:05 [DBG] wrote db '/home/beni/fgcom-web.db.part'
2024-02-17 02:42:05 [DBG] published db '/home/beni/fgcom-web.db'

Interestingly, /home/beni/fgcom-web.db.part is still opened, but remains at 0 bytes.

hbeni commented 9 months ago

Suspicious: The dbg message from fgcom.data.cleanupPluginData() does not show up in any log. Looks like it's never doing something.

hbeni commented 9 months ago

Somehow it looks like the db output generation timer stats to "hang". Maybe this is some access race condition from the updater?

I added more log messages, I hope I can better detect the origin of the problem now.

[x] Interestingly, the website did not mark the DB as outdated, despite it was clearly so. Was marked, but stale class was wrongly added to the HTML-element. Fixed in e32b501bb39282c684f580e0f4dce2b51e5419a0

hbeni commented 8 months ago

Ocurred again, last file db update was 18:00:05 (local time, like in the log).

  File: fgcom-usage.stats
  Size: 14709477        Blocks: 28744      IO Block: 4096   regular file
Device: 8,1     Inode: 2097546     Links: 1
Access: (0644/-rw-r--r--)  Uid: ( 1000/    user)   Gid: ( 1000/    user)
Access: 2024-03-06 07:57:20.452074389 +0100
Modify: 2024-03-06 08:08:05.473056166 +0100
Change: 2024-03-06 08:08:05.473056166 +0100
 Birth: 2024-03-04 03:00:01.424485407 +0100

  File: fgcom-web.db
  Size: 902             Blocks: 8          IO Block: 4096   regular file
Device: 8,1     Inode: 1445873     Links: 1
Access: (0644/-rw-r--r--)  Uid: ( 1000/    user)   Gid: ( 1000/    user)
Access: 2024-03-05 18:48:53.879270713 +0100
Modify: 2024-03-03 18:00:05.474110312 +0100
Change: 2024-03-03 18:00:05.474110312 +0100
 Birth: 2024-03-03 18:00:05.474110312 +0100

Filesize of statusbot.log is a whopping 1.7GB. fgcom-usage.stats just shows the radio bot but clients remain empty even with clients connected. This shows some "hanging" of the bot. (But the radio bot still doing it's thing, and the infrastructure remains functional). Statuspage now correctly reports the DB is outdated: Last DB update: 03.03.2024 17:00:05 (UTC)

Last publish was:

2024-03-03 18:00:05 [DBG] opened stats file '/home/beni/fgcom-usage.stats'
2024-03-03 18:00:05 [DBG] wrote stats to '/home/beni/fgcom-usage.stats' (1 users)
2024-03-03 18:00:05 [DBG] Update db '/home/beni/fgcom-web.db'
2024-03-03 18:00:05 [DBG] opened db '/home/beni/fgcom-web.db.part'
2024-03-03 18:00:05 [DBG] generateOutData(): processing user: 2 with idty=0
2024-03-03 18:00:05 [DBG]   callsign=wesnothSAT (type=playback-bot)
2024-03-03 18:00:05 [DBG]   radio #0, ptt='1', frq='0.345', dialedFRQ='0.345', operable=1
2024-03-03 18:00:05 [DBG]   updated=1709485202
2024-03-03 18:00:05 [DBG]   lat=45.0; lon=-30.0; alt=10000000
2024-03-03 18:00:05 [DBG] generateOutData(): processing user: 2 with idty=0
2024-03-03 18:00:05 [DBG]   callsign=wesnothSAT (type=playback-bot)
2024-03-03 18:00:05 [DBG]   radio #0, ptt='1', frq='0.345', dialedFRQ='0.345', operable=1
2024-03-03 18:00:05 [DBG]   updated=1709485202
2024-03-03 18:00:05 [DBG]   lat=45.0; lon=-30.0; alt=10000000
2024-03-03 18:00:05 [DBG] generateOutData(): processing user: 96 with idty=0
2024-03-03 18:00:05 [DBG]   callsign=efg13 (type=client)
2024-03-03 18:00:05 [DBG]   radio #0, ptt='1', frq='910.0000', dialedFRQ='910', operable=1
2024-03-03 18:00:05 [DBG]   radio #1, ptt='0', frq='128.3000', dialedFRQ='128.3', operable=1
2024-03-03 18:00:05 [DBG]   updated=1709485205
2024-03-03 18:00:05 [DBG]   lat=41.775887; lon=12.233772; alt=-8668.921875
2024-03-03 18:00:05 [DBG] generateOutData(): generating highscore data...
2024-03-03 18:00:05 [DBG] generateOutData(): generating db content...
2024-03-03 18:00:05 [DBG] JSON RESULT: {"clients":[{"lat":"45.0","lon":"-30.0","alt":"10000000","radios":{"0":{"ptt":"1","power":"10000","pbt":1,"frequency":"0.345","srv":1,"dialedFRQ":"0.345","vlt":12,"operable":1}},"type":"playback-bot","callsign":"wesnothSAT","updated":1709485202},{"lat":"45.0","lon":"-30.0","alt":"10000000","radios":{"0":{"ptt":"1","power":"10000","pbt":1,"frequency":"0.345","srv":1,"dialedFRQ":"0.345","vlt":12,"operable":1}},"type":"playback-bot","callsign":"wesnothSAT","updated":1709485202},{"lat":"41.775887","lon":"12.233772","alt":"-8668.921875","radios":{"0":{"ptt":"1","power":"10.000000","pbt":1,"frequency":"910.0000","srv":1,"dialedFRQ":"910","vlt":12,"operable":"1"},"1":{"ptt":"0","power":"10.000000","pbt":1,"frequency":"128.3000","srv":1,"dialedFRQ":"128.3","vlt":12,"operable":"1"}},"type":"client","callsign":"efg13","updated":1709485205}],"meta":{"highscore_date":1708468045,"highscore_clients":2}}
2024-03-03 18:00:05 [DBG] db data generating completed
2024-03-03 18:00:05 [DBG] wrote db '/home/beni/fgcom-web.db.part'
2024-03-03 18:00:05 [DBG] published db '/home/beni/fgcom-web.db'

Remote state before the bug occurs:

2024-03-03 18:00:20 [DBG] Parsing done. New remote state:
2024-03-03 18:00:20 [DBG] sid=2; idty=0 lat:    45.0
2024-03-03 18:00:20 [DBG] sid=2; idty=0 lon:    -30.0
2024-03-03 18:00:20 [DBG] sid=2; idty=0 alt:    10000000
2024-03-03 18:00:20 [DBG] sid=2; idty=0    radio #0 frequency='0.345'
2024-03-03 18:00:20 [DBG] sid=2; idty=0    radio #0 dialedFRQ='0.345'
2024-03-03 18:00:20 [DBG] sid=2; idty=0    radio #0       ptt='1'
2024-03-03 18:00:20 [DBG] sid=2; idty=0    radio #0       pwr='10000'
2024-03-03 18:00:20 [DBG] sid=2; idty=0    radio #0       opr='1'
2024-03-03 18:00:20 [DBG] sid=2; idty=0 lastUpdate:     1709485212
2024-03-03 18:00:20 [DBG] sid=2; idty=0 callsign:       wesnothSAT
2024-03-03 18:00:20 [DBG] sid=2; idty=0 type:   playback-bot
2024-03-03 18:00:20 [DBG] sid=98; idty=0        lat:    41.775654
2024-03-03 18:00:20 [DBG] sid=98; idty=0        lon:    12.233780
2024-03-03 18:00:20 [DBG] sid=98; idty=0        alt:    -8826.810547
2024-03-03 18:00:20 [DBG] sid=98; idty=0    radio #0 frequency='910.00'
2024-03-03 18:00:20 [DBG] sid=98; idty=0    radio #0 dialedFRQ='910.00'
2024-03-03 18:00:20 [DBG] sid=98; idty=0    radio #0       ptt='0'
2024-03-03 18:00:20 [DBG] sid=98; idty=0    radio #0       pwr='10.000000'
2024-03-03 18:00:20 [DBG] sid=98; idty=0    radio #0       opr='1'
2024-03-03 18:00:20 [DBG] sid=98; idty=0        lastUpdate:     1709485216
2024-03-03 18:00:20 [DBG] sid=98; idty=0        callsign:       ECHO:efg13
2024-03-03 18:00:20 [DBG] sid=98; idty=0        type:   playback-bot
2024-03-03 18:00:20 [DBG] sid=97; idty=0        lat:    41.775887
2024-03-03 18:00:20 [DBG] sid=97; idty=0        lon:    12.233772
2024-03-03 18:00:20 [DBG] sid=97; idty=0        alt:    -8668.921875
2024-03-03 18:00:20 [DBG] sid=97; idty=0    radio #0 frequency='910.00'
2024-03-03 18:00:20 [DBG] sid=97; idty=0    radio #0 dialedFRQ='910.00'
2024-03-03 18:00:20 [DBG] sid=97; idty=0    radio #0       ptt='0'
2024-03-03 18:00:20 [DBG] sid=97; idty=0    radio #0       pwr='10.000000'
2024-03-03 18:00:20 [DBG] sid=97; idty=0    radio #0       opr='1'
2024-03-03 18:00:20 [DBG] sid=97; idty=0        lastUpdate:     1709485209
2024-03-03 18:00:20 [DBG] sid=97; idty=0        callsign:       ECHO:efg13
2024-03-03 18:00:20 [DBG] sid=96; idty=0        lat:    41.775444
2024-03-03 18:00:20 [DBG] sid=96; idty=0        lon:    12.233787
2024-03-03 18:00:20 [DBG] sid=96; idty=0        alt:    -8970.982422
2024-03-03 18:00:20 [DBG] sid=96; idty=0    radio #0 frequency='910.0000'
2024-03-03 18:00:20 [DBG] sid=96; idty=0    radio #0 dialedFRQ='910'
2024-03-03 18:00:20 [DBG] sid=96; idty=0    radio #0       ptt='0'
2024-03-03 18:00:20 [DBG] sid=96; idty=0    radio #0       pwr='10.000000'
2024-03-03 18:00:20 [DBG] sid=96; idty=0    radio #0       opr='1'
2024-03-03 18:00:20 [DBG] sid=96; idty=0    radio #1 frequency='128.3000'
2024-03-03 18:00:20 [DBG] sid=96; idty=0    radio #1 dialedFRQ='128.3'
2024-03-03 18:00:20 [DBG] sid=96; idty=0    radio #1       ptt='0'
2024-03-03 18:00:20 [DBG] sid=96; idty=0    radio #1       pwr='10.000000'
2024-03-03 18:00:20 [DBG] sid=96; idty=0    radio #1       opr='1'
2024-03-03 18:00:20 [DBG] sid=96; idty=0        lastUpdate:     1709485220
2024-03-03 18:00:20 [DBG] sid=96; idty=0        callsign:       efg13
2024-03-03 18:00:20 [DBG] sid=96; idty=0        type:   client
2024-03-03 18:00:20 [DBG] -----------

Next update does not finish:

2024-03-03 18:00:20 [DBG] -----------
2024-03-03 18:00:20 [DBG] Update db '/home/beni/fgcom-web.db'
2024-03-03 18:00:20 [DBG] opened db '/home/beni/fgcom-web.db.part'
2024-03-03 18:00:20 [DBG] generateOutData(): processing user: 2 with idty=0
2024-03-03 18:00:20 [DBG]   callsign=wesnothSAT (type=playback-bot)
2024-03-03 18:00:20 [DBG]   radio #0, ptt='1', frq='0.345', dialedFRQ='0.345', operable=1
2024-03-03 18:00:20 [DBG]   updated=1709485212
2024-03-03 18:00:20 [DBG]   lat=45.0; lon=-30.0; alt=10000000
2024-03-03 18:00:20 [DBG] generateOutData(): processing user: 2 with idty=0
2024-03-03 18:00:20 [DBG]   callsign=wesnothSAT (type=playback-bot)
2024-03-03 18:00:20 [DBG]   radio #0, ptt='1', frq='0.345', dialedFRQ='0.345', operable=1
2024-03-03 18:00:20 [DBG]   updated=1709485212
2024-03-03 18:00:20 [DBG]   lat=45.0; lon=-30.0; alt=10000000
2024-03-03 18:00:20 [DBG] generateOutData(): processing user: 98 with idty=0
2024-03-03 18:00:20 [DBG] User sid=98 not connected anymore!
2024-03-03 18:00:20 [DBG]   callsign=ECHO:efg13 (type=playback-bot)
2024-03-03 18:00:20 [DBG]   radio #0, ptt='0', frq='910.00', dialedFRQ='910.00', operable=1
2024-03-03 18:00:20 [DBG]   updated=1709485216
2024-03-03 18:00:20 [DBG]   lat=41.775654; lon=12.233780; alt=-8826.810547
2024-03-03 18:00:20 [DBG] generateOutData(): processing user: 97 with idty=0
2024-03-03 18:00:20 [DBG] User sid=97 not connected anymore!
2024-03-03 18:00:21 [DBG] DATA INCOMING FROM=96
2024-03-03 18:00:21 [DBG] Received FGCOM-plugin data, dataID='FGCOM:UPD_LOC:0', from=[96] 'efg13'

Parsing of my test connections plugin data still succeeds. I'm in the remote state of the bot. I think, somehow the output process is not able to write data anymore (and no, disk is not full :grin: )

2024-03-06 08:05:04 [DBG] sid=118; idty=0       lat:    48.344025
2024-03-06 08:05:04 [DBG] sid=118; idty=0       lon:    11.765083
2024-03-06 08:05:04 [DBG] sid=118; idty=0       alt:    2.011704
2024-03-06 08:05:04 [DBG] sid=118; idty=0    radio #0 frequency='.345'
2024-03-06 08:05:04 [DBG] sid=118; idty=0    radio #0 dialedFRQ='0.345'
2024-03-06 08:05:04 [DBG] sid=118; idty=0    radio #0       ptt='0'
2024-03-06 08:05:04 [DBG] sid=118; idty=0    radio #0       pwr='10.000000'
2024-03-06 08:05:04 [DBG] sid=118; idty=0    radio #0       opr='1'
2024-03-06 08:05:04 [DBG] sid=118; idty=0       lastUpdate:     1709708704
2024-03-06 08:05:04 [DBG] sid=118; idty=0       callsign:       tewt

hbeni commented 8 months ago

Looks like, the generateOutData() function is ended prematurely after the if branch at line 139. The debug out in line 154, which should print the callsign, is not executed anymore.

Looking at the data, sid=97 has no type field. :warning: This causes a nil to be stored there in line 143.

Maybe.... #177 is the root cause for this, and we run into some nil reference in the table?

hbeni commented 8 months ago

The bot was restarted with the PRs code 2024-03-10 01:20:43 (utc+1). Did not occur so far, but its early to say; the bug took a week or two to manifest so far.

Continuing watching this. :eyes:

hbeni / fgcom-mumble

Bug: Statuspage / Statusbot not displaying clients after long runtime #174