Bug: server/statubot starts to output missing/crippled database after some time

hbeni commented 1 year ago

Describe the bug After a while(?), the statusbot does not output correct database anymore. This leads to wrong presentation on the statuspage (php error output was adressed in 02da174 recently). Namely, the displayed client has for example no callsign or no location information.

To Reproduce unknown, but it was enough to connect to the system when the bot had run for a while.

Expected behavior Normal display of the client (correct information replayed in the database)

Logfiles Stored at test server instance, but producable with the --slog ... botmanager directive

Noted causes:

[x] :lady_beetle: reestablishing sending data to already running plugin instance => The local last notified state is not cleared when the IID is collected from the garbage collector. When it is cleared, we would send a new Locstat package once the first locstat is beeing received from the UDP server by the plugin. (306ec32 :heavy_check_mark: ) => (as fallback, low prio :arrow_down:) Statusbot needs to reask for missing state on incoming PING packages
[x] Database missing info with long running statusbot and fresh connections (comment: reproduce info) => JSON lua module seemed to be the cause

hbeni commented 1 year ago

DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:ICANHAZDATAPLZ', from=[48] 'D-EBHX'
  data='allYourDataBelongsToUs!'
  datatype='FGCOM'
  packtype='ICANHAZDATAPLZ'
Parsing done. New remote state:
-----------
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":{}}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":{}}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:UPD_COM:0:0', from=[48] 'D-EBHX'
  data='FRQ=121.0000,CHN=121.000,PTT=0,PWR=10.000000,OPR=1'
  datatype='FGCOM'
  packtype='UPD_COM'
  iid='0'
added new client state: 48
parsing field: FRQ=121.0000
  radioID='0'
parsing field: CHN=121.000
  radioID='0'
parsing field: PTT=0
  radioID='0'
parsing field: PWR=10.000000
  radioID='0'
parsing field: OPR=1
  radioID='0'
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0  lastUpdate:     1688975534
sid=48; idty=0  callsign:
sid=48; idty=0  lat:
sid=48; idty=0  lon:
sid=48; idty=0  alt:
-----------
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:UPD_COM:0:1', from=[48] 'D-EBHX'
  data='FRQ=122.54167,CHN=122.540,PTT=0,PWR=10.000000,OPR=1'
  datatype='FGCOM'
  packtype='UPD_COM'
  iid='0'
parsing field: FRQ=122.54167
  radioID='1'
parsing field: CHN=122.540
  radioID='1'
parsing field: PTT=0
  radioID='1'
parsing field: PWR=10.000000
  radioID='1'
parsing field: OPR=1
  radioID='1'
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0    radio #1 frequency='122.54167'
sid=48; idty=0    radio #1 dialedFRQ='122.540'
sid=48; idty=0    radio #1       ptt='0'
sid=48; idty=0    radio #1       pwr='10.000000'
sid=48; idty=0    radio #1       opr='1'
sid=48; idty=0  lastUpdate:     1688975534
sid=48; idty=0  callsign:
sid=48; idty=0  lat:
sid=48; idty=0  lon:
sid=48; idty=0  alt:
-----------
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:PING', from=[48] 'D-EBHX'
  data='0'
  datatype='FGCOM'
  packtype='PING'
ping packet for sid=48; iid=0
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0    radio #1 frequency='122.54167'
sid=48; idty=0    radio #1 dialedFRQ='122.540'
sid=48; idty=0    radio #1       ptt='0'
sid=48; idty=0    radio #1       pwr='10.000000'
sid=48; idty=0    radio #1       opr='1'
sid=48; idty=0  lastUpdate:     1688975534
sid=48; idty=0  callsign:
sid=48; idty=0  lat:
sid=48; idty=0  lon:
sid=48; idty=0  alt:
-----------
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:UPD_LOC:0', from=[48] 'D-EBHX'
  data='LAT=48.344025,LON=11.765083,ALT=2.011704,'
  datatype='FGCOM'
  packtype='UPD_LOC'
  iid='0'
parsing field: LAT=48.344025
parsing field: LON=11.765083
parsing field: ALT=2.011704
parsing field failed! 1 tokens seen
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0    radio #1 frequency='122.54167'
sid=48; idty=0    radio #1 dialedFRQ='122.540'
sid=48; idty=0    radio #1       ptt='0'
sid=48; idty=0    radio #1       pwr='10.000000'
sid=48; idty=0    radio #1       opr='1'
sid=48; idty=0  lastUpdate:     1688975534
sid=48; idty=0  callsign:
sid=48; idty=0  lat:    48.344025
sid=48; idty=0  lon:    11.765083
sid=48; idty=0  alt:    2.011704
-----------
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688975534, "alt":"2.011704", "callsign":"", "lat":"48.344025", "lon":"11.765083", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688975534, "alt":"2.011704", "callsign":"", "lat":"48.344025", "lon":"11.765083", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:PING', from=[48] 'D-EBHX'
  data='0'
  datatype='FGCOM'
  packtype='PING'
ping packet for sid=48; iid=0
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0    radio #1 frequency='122.54167'
sid=48; idty=0    radio #1 dialedFRQ='122.540'
sid=48; idty=0    radio #1       ptt='0'
sid=48; idty=0    radio #1       pwr='10.000000'
sid=48; idty=0    radio #1       opr='1'
sid=48; idty=0  type:   client
sid=48; idty=0  lastUpdate:     1688975544
sid=48; idty=0  callsign:
sid=48; idty=0  lat:    48.344025
sid=48; idty=0  lon:    11.765083
sid=48; idty=0  alt:    2.011704
-----------
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688975544, "alt":"2.011704", "callsign":"", "lat":"48.344025", "lon":"11.765083", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688975544, "alt":"2.011704", "callsign":"", "lat":"48.344025", "lon":"11.765083", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:PING', from=[48] 'D-EBHX'
  data='0'
  datatype='FGCOM'
  packtype='PING'
ping packet for sid=48; iid=0
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0    radio #1 frequency='122.54167'
sid=48; idty=0    radio #1 dialedFRQ='122.540'
sid=48; idty=0    radio #1       ptt='0'
sid=48; idty=0    radio #1       pwr='10.000000'
sid=48; idty=0    radio #1       opr='1'
sid=48; idty=0  type:   client
sid=48; idty=0  lastUpdate:     1688975554
sid=48; idty=0  callsign:
sid=48; idty=0  lat:    48.344025
sid=48; idty=0  lon:    11.765083
sid=48; idty=0  alt:    2.011704
-----------
opened stats file '/home/beni/fgcom-usage.stats'
wrote stats to '/home/beni/fgcom-usage.stats' (1 users)
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688975554, "alt":"2.011704", "callsign":"", "lat":"48.344025", "lon":"11.765083", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688975554, "alt":"2.011704", "callsign":"", "lat":"48.344025", "lon":"11.765083", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:PING', from=[48] 'D-EBHX'
  data='0'
  datatype='FGCOM'
  packtype='PING'
ping packet for sid=48; iid=0
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0    radio #1 frequency='122.54167'
sid=48; idty=0    radio #1 dialedFRQ='122.540'
sid=48; idty=0    radio #1       ptt='0'
sid=48; idty=0    radio #1       pwr='10.000000'
sid=48; idty=0    radio #1       opr='1'
sid=48; idty=0  type:   client
sid=48; idty=0  lastUpdate:     1688975564
sid=48; idty=0  callsign:
sid=48; idty=0  lat:    48.344025
sid=48; idty=0  lon:    11.765083
sid=48; idty=0  alt:    2.011704
-----------
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688975564, "alt":"2.011704", "callsign":"", "lat":"48.344025", "lon":"11.765083", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688975564, "alt":"2.011704", "callsign":"", "lat":"48.344025", "lon":"11.765083", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:PING', from=[48] 'D-EBHX'
  data='0'
  datatype='FGCOM'
  packtype='PING'
ping packet for sid=48; iid=0
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0    radio #1 frequency='122.54167'
sid=48; idty=0    radio #1 dialedFRQ='122.540'
sid=48; idty=0    radio #1       ptt='0'
sid=48; idty=0    radio #1       pwr='10.000000'
sid=48; idty=0    radio #1       opr='1'
sid=48; idty=0  type:   client
sid=48; idty=0  lastUpdate:     1688975574
sid=48; idty=0  callsign:
sid=48; idty=0  lat:    48.344025
sid=48; idty=0  lon:    11.765083
sid=48; idty=0  alt:    2.011704
-----------
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688975574, "alt":"2.011704", "callsign":"", "lat":"48.344025", "lon":"11.765083", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688975574, "alt":"2.011704", "callsign":"", "lat":"48.344025", "lon":"11.765083", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:PING', from=[48] 'D-EBHX'
  data='0'
  datatype='FGCOM'
  packtype='PING'
ping packet for sid=48; iid=0
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0    radio #1 frequency='122.54167'
sid=48; idty=0    radio #1 dialedFRQ='122.540'
sid=48; idty=0    radio #1       ptt='0'
sid=48; idty=0    radio #1       pwr='10.000000'
sid=48; idty=0    radio #1       opr='1'
sid=48; idty=0  type:   client
sid=48; idty=0  lastUpdate:     1688975584
sid=48; idty=0  callsign:
sid=48; idty=0  lat:    48.344025
sid=48; idty=0  lon:    11.765083
sid=48; idty=0  alt:    2.011704
-----------
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688975584, "alt":"2.011704", "callsign":"", "lat":"48.344025", "lon":"11.765083", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688975584, "alt":"2.011704", "callsign":"", "lat":"48.344025", "lon":"11.765083", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:PING', from=[48] 'D-EBHX'
  data='0'
  datatype='FGCOM'
  packtype='PING'
ping packet for sid=48; iid=0
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0    radio #1 frequency='122.54167'
sid=48; idty=0    radio #1 dialedFRQ='122.540'
sid=48; idty=0    radio #1       ptt='0'
sid=48; idty=0    radio #1       pwr='10.000000'
sid=48; idty=0    radio #1       opr='1'
sid=48; idty=0  type:   client
sid=48; idty=0  lastUpdate:     1688975594
sid=48; idty=0  callsign:
sid=48; idty=0  lat:    48.344025
sid=48; idty=0  lon:    11.765083
sid=48; idty=0  alt:    2.011704
-----------
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688975594, "alt":"2.011704", "callsign":"", "lat":"48.344025", "lon":"11.765083", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'

hbeni commented 1 year ago

After callsign change:

-----------
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:UPD_USR:0', from=[48] 'D-EBHX'
  data='CALLSIGN=bla'
  datatype='FGCOM'
  packtype='UPD_USR'
  iid='0'
parsing field: CALLSIGN=bla
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0    radio #1 frequency='122.54167'
sid=48; idty=0    radio #1 dialedFRQ='122.540'
sid=48; idty=0    radio #1       ptt='0'
sid=48; idty=0    radio #1       pwr='10.000000'
sid=48; idty=0    radio #1       opr='1'
sid=48; idty=0  type:   client
sid=48; idty=0  lastUpdate:     1688975751
sid=48; idty=0  callsign:       bla
sid=48; idty=0  lat:    48.344025
sid=48; idty=0  lon:    11.765083
sid=48; idty=0  alt:    2.011704
-----------

Maybe the USR data packet is not ever actively sent to new users when joining the server? Or not transmitted when asked for by the plugin? EDIT: Code should correctly transmit/parse; but this needs more debugging with logs (client/server together)

hbeni commented 1 year ago

Reconnecting a disconnected client (mumble instance was still running all the time) yielded this:

DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:UPD_USR:0', from=[48] 'D-EBHX'
  data='CALLSIGN=bla'
  datatype='FGCOM'
  packtype='UPD_USR'
  iid='0'
parsing field: CALLSIGN=bla
Parsing done. New remote state:
sid=48; idty=0  lastUpdate:     1688979865
sid=48; idty=0  callsign:       bla
sid=48; idty=0  lat:
sid=48; idty=0  lon:
sid=48; idty=0  alt:
-----------
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:UPD_COM:0:0', from=[48] 'D-EBHX'
  data='FRQ=121.0000,CHN=121.000,PTT=0,PWR=10.000000,OPR=1'
  datatype='FGCOM'
  packtype='UPD_COM'
  iid='0'
parsing field: FRQ=121.0000
  radioID='0'
parsing field: CHN=121.000
  radioID='0'
parsing field: PTT=0
  radioID='0'
parsing field: PWR=10.000000
  radioID='0'
parsing field: OPR=1
  radioID='0'
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0  lastUpdate:     1688979865
sid=48; idty=0  callsign:       bla
sid=48; idty=0  lat:
sid=48; idty=0  lon:
sid=48; idty=0  alt:
-----------
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:UPD_COM:0:1', from=[48] 'D-EBHX'
  data='FRQ=122.54167,CHN=122.540,PTT=0,PWR=8.000000,OPR=1'
  datatype='FGCOM'
  packtype='UPD_COM'
  iid='0'
parsing field: FRQ=122.54167
  radioID='1'
parsing field: CHN=122.540
  radioID='1'
parsing field: PTT=0
  radioID='1'
parsing field: PWR=8.000000
  radioID='1'
parsing field: OPR=1
  radioID='1'
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0    radio #1 frequency='122.54167'
sid=48; idty=0    radio #1 dialedFRQ='122.540'
sid=48; idty=0    radio #1       ptt='0'
sid=48; idty=0    radio #1       pwr='8.000000'
sid=48; idty=0    radio #1       opr='1'
sid=48; idty=0  lastUpdate:     1688979865
sid=48; idty=0  callsign:       bla
sid=48; idty=0  lat:
sid=48; idty=0  lon:
sid=48; idty=0  alt:
-----------
DATA INCOMING FROM=48
Received FGCOM-plugin data, dataID='FGCOM:PING', from=[48] 'D-EBHX'
  data='0'
  datatype='FGCOM'
  packtype='PING'
ping packet for sid=48; iid=0
Parsing done. New remote state:
sid=48; idty=0    radio #0 frequency='121.0000'
sid=48; idty=0    radio #0 dialedFRQ='121.000'
sid=48; idty=0    radio #0       ptt='0'
sid=48; idty=0    radio #0       pwr='10.000000'
sid=48; idty=0    radio #0       opr='1'
sid=48; idty=0    radio #1 frequency='122.54167'
sid=48; idty=0    radio #1 dialedFRQ='122.540'
sid=48; idty=0    radio #1       ptt='0'
sid=48; idty=0    radio #1       pwr='8.000000'
sid=48; idty=0    radio #1       opr='1'
sid=48; idty=0  lastUpdate:     1688979865
sid=48; idty=0  callsign:       bla
sid=48; idty=0  lat:
sid=48; idty=0  lon:
sid=48; idty=0  alt:
-----------
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"8.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688979865, "alt":"", "callsign":"bla", "lat":"", "lon":"", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 48 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"8.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688979865, "alt":"", "callsign":"bla", "lat":"", "lon":"", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
DATA INCOMING FROM=48

The LOC package was not registered server side. Server log did not record dropped packages

hbeni commented 1 year ago

Reconnect shows that the plugin justs sends UPD_USR and UPD_COMpackages. This might be a plugin bug.

FGCom [2023-07-10 11:28:28.973]: [DBG] [mum_pluginIO] notifyRemotes(0,4,-1,0) called
FGCom [2023-07-10 11:28:28.973]: [DBG] [mum_pluginIO] notifyRemotes(): we are connected, so notifications will be sent.
FGCom [2023-07-10 11:28:28.973]: [DBG] [mum_pluginIO] notifyRemotes(): successfully resolved identity='0' (callsign=test)
FGCom [2023-07-10 11:28:28.973]: [DBG] [mum_pluginIO] notifyRemotes(): selected: userdata
FGCom [2023-07-10 11:28:28.973]: [DBG] There are 3 users on this channel.
FGCom [2023-07-10 11:28:28.973]: [DBG]   sending message to: 47
FGCom [2023-07-10 11:28:28.973]: [DBG]   sending message to: 46
FGCom [2023-07-10 11:28:28.973]: [DBG]   ignored local user: id=51
FGCom [2023-07-10 11:28:28.974]: [DBG]   message sent to 2 clients
FGCom [2023-07-10 11:28:28.974]: [DBG] [mum_pluginIO] message was: 'CALLSIGN=test'
FGCom [2023-07-10 11:28:28.974]: [DBG] [mum_pluginIO] notification for dataID='FGCOM:UPD_USR:0' done.
FGCom [2023-07-10 11:28:28.979]: [DBG] [mum_pluginIO] notifyRemotes(0,2,0,0) called
FGCom [2023-07-10 11:28:28.979]: [DBG] [mum_pluginIO] notifyRemotes(): we are connected, so notifications will be sent.
FGCom [2023-07-10 11:28:28.979]: [DBG] [mum_pluginIO] notifyRemotes(): successfully resolved identity='0' (callsign=test)
FGCom [2023-07-10 11:28:28.979]: [DBG] [mum_pluginIO] notifyRemotes(): selected radio
FGCom [2023-07-10 11:28:28.979]: [DBG] [mum_pluginIO] notifyRemotes():    send state of COM1
FGCom [2023-07-10 11:28:28.979]: [DBG] There are 3 users on this channel.
FGCom [2023-07-10 11:28:28.979]: [DBG]   sending message to: 47
FGCom [2023-07-10 11:28:28.979]: [DBG]   sending message to: 46
FGCom [2023-07-10 11:28:28.979]: [DBG]   ignored local user: id=51
FGCom [2023-07-10 11:28:28.979]: [DBG]   message sent to 2 clients
FGCom [2023-07-10 11:28:28.979]: [DBG] [mum_pluginIO] notification for dataID='FGCOM:UPD_COM:0:0' done.
FGCom [2023-07-10 11:28:28.980]: [DBG] [mum_pluginIO] notifyRemotes(0,2,1,0) called
FGCom [2023-07-10 11:28:28.980]: [DBG] [mum_pluginIO] notifyRemotes(): we are connected, so notifications will be sent.
FGCom [2023-07-10 11:28:28.980]: [DBG] [mum_pluginIO] notifyRemotes(): successfully resolved identity='0' (callsign=test)
FGCom [2023-07-10 11:28:28.980]: [DBG] [mum_pluginIO] notifyRemotes(): selected radio
FGCom [2023-07-10 11:28:28.980]: [DBG] [mum_pluginIO] notifyRemotes():    send state of COM2
FGCom [2023-07-10 11:28:28.980]: [DBG] There are 3 users on this channel.
FGCom [2023-07-10 11:28:28.980]: [DBG]   sending message to: 47
FGCom [2023-07-10 11:28:28.980]: [DBG]   sending message to: 46
FGCom [2023-07-10 11:28:28.980]: [DBG]   ignored local user: id=51
FGCom [2023-07-10 11:28:28.980]: [DBG]   message sent to 2 clients
FGCom [2023-07-10 11:28:28.980]: [DBG] [mum_pluginIO] notification for dataID='FGCOM:UPD_COM:0:1' done.

FGCom [2023-07-10 11:28:29.317]: [DBG] [mum_pluginIO] fgcom_notifyThread() userdata was changed.
FGCom [2023-07-10 11:28:29.317]: [DBG] [mum_pluginIO] notifyRemotes(0,4,-1,0) called
FGCom [2023-07-10 11:28:29.317]: [DBG] [mum_pluginIO] notifyRemotes(): we are connected, so notifications will be sent.
FGCom [2023-07-10 11:28:29.317]: [DBG] [mum_pluginIO] notifyRemotes(): successfully resolved identity='0' (callsign=test)
FGCom [2023-07-10 11:28:29.317]: [DBG] [mum_pluginIO] notifyRemotes(): selected: userdata
FGCom [2023-07-10 11:28:29.317]: [DBG] There are 3 users on this channel.
FGCom [2023-07-10 11:28:29.317]: [DBG]   sending message to: 47
FGCom [2023-07-10 11:28:29.318]: [DBG]   sending message to: 46
FGCom [2023-07-10 11:28:29.318]: [DBG]   ignored local user: id=51
FGCom [2023-07-10 11:28:29.318]: [DBG]   message sent to 2 clients
FGCom [2023-07-10 11:28:29.318]: [DBG] [mum_pluginIO] message was: 'CALLSIGN=test'
FGCom [2023-07-10 11:28:29.318]: [DBG] [mum_pluginIO] notification for dataID='FGCOM:UPD_USR:0' done.

DATA INCOMING FROM=51
Received FGCOM-plugin data, dataID='FGCOM:UPD_USR:0', from=[51] 'D-EBHX'
  data='CALLSIGN=test'
  datatype='FGCOM'
  packtype='UPD_USR'
  iid='0'
parsing field: CALLSIGN=test
Parsing done. New remote state:
sid=51; idty=0  lastUpdate:     1688981308
sid=51; idty=0  callsign:       test
sid=51; idty=0  lat:
sid=51; idty=0  lon:
sid=51; idty=0  alt:
-----------
DATA INCOMING FROM=51
Received FGCOM-plugin data, dataID='FGCOM:UPD_COM:0:0', from=[51] 'D-EBHX'
  data='FRQ=121.0000,CHN=121.000,PTT=0,PWR=10.000000,OPR=1'
  datatype='FGCOM'
  packtype='UPD_COM'
  iid='0'
parsing field: FRQ=121.0000
  radioID='0'
parsing field: CHN=121.000
  radioID='0'
parsing field: PTT=0
  radioID='0'
parsing field: PWR=10.000000
  radioID='0'
parsing field: OPR=1
  radioID='0'
Parsing done. New remote state:
sid=51; idty=0    radio #0 frequency='121.0000'
sid=51; idty=0    radio #0 dialedFRQ='121.000'
sid=51; idty=0    radio #0       ptt='0'
sid=51; idty=0    radio #0       pwr='10.000000'
sid=51; idty=0    radio #0       opr='1'
sid=51; idty=0  lastUpdate:     1688981309
sid=51; idty=0  callsign:       test
sid=51; idty=0  lat:
sid=51; idty=0  lon:
sid=51; idty=0  alt:
-----------
DATA INCOMING FROM=51
Received FGCOM-plugin data, dataID='FGCOM:UPD_COM:0:1', from=[51] 'D-EBHX'
  data='FRQ=122.54167,CHN=122.540,PTT=0,PWR=8.000000,OPR=1'
  datatype='FGCOM'
  packtype='UPD_COM'
  iid='0'
parsing field: FRQ=122.54167
  radioID='1'
parsing field: CHN=122.540
  radioID='1'
parsing field: PTT=0
  radioID='1'
parsing field: PWR=8.000000
  radioID='1'
parsing field: OPR=1
  radioID='1'
Parsing done. New remote state:
sid=51; idty=0    radio #0 frequency='121.0000'
sid=51; idty=0    radio #0 dialedFRQ='121.000'
sid=51; idty=0    radio #0       ptt='0'
sid=51; idty=0    radio #0       pwr='10.000000'
sid=51; idty=0    radio #0       opr='1'
sid=51; idty=0    radio #1 frequency='122.54167'
sid=51; idty=0    radio #1 dialedFRQ='122.540'
sid=51; idty=0    radio #1       ptt='0'
sid=51; idty=0    radio #1       pwr='8.000000'
sid=51; idty=0    radio #1       opr='1'
sid=51; idty=0  lastUpdate:     1688981309
sid=51; idty=0  callsign:       test
sid=51; idty=0  lat:
sid=51; idty=0  lon:
sid=51; idty=0  alt:
-----------
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 51 with idty=0
  check frequency: radio #0, ptt='0', frq='121.0000', dialedFRQ='121.000', operable=1
  check frequency: radio #1, ptt='0', frq='122.54167', dialedFRQ='122.540', operable=1
JSON RESULT: {"meta":{"highscore_clients":1, "highscore_date":1688930220}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"121.000", "vlt":12, "operable":"1", "ptt":"0", "power":"10.000000", "pbt":1, "frequency":"121.0000"}, "1":{"srv":1, "dialedFRQ":"122.540", "vlt":12, "operable":"1", "ptt":"0", "power":"8.000000", "pbt":1, "frequency":"122.54167"}}, "updated":1688981309, "alt":"", "callsign":"test", "lat":"", "lon":"", "type":"client"}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'
DATA INCOMING FROM=51
Received FGCOM-plugin data, dataID='FGCOM:UPD_USR:0', from=[51] 'D-EBHX'
  data='CALLSIGN=test'
  datatype='FGCOM'
  packtype='UPD_USR'
  iid='0'
parsing field: CALLSIGN=test
Parsing done. New remote state:
sid=51; idty=0    radio #0 frequency='121.0000'
sid=51; idty=0    radio #0 dialedFRQ='121.000'
sid=51; idty=0    radio #0       ptt='0'
sid=51; idty=0    radio #0       pwr='10.000000'
sid=51; idty=0    radio #0       opr='1'
sid=51; idty=0    radio #1 frequency='122.54167'
sid=51; idty=0    radio #1 dialedFRQ='122.540'
sid=51; idty=0    radio #1       ptt='0'
sid=51; idty=0    radio #1       pwr='8.000000'
sid=51; idty=0    radio #1       opr='1'
sid=51; idty=0  type:   client
sid=51; idty=0  lastUpdate:     1688981309
sid=51; idty=0  callsign:       test
sid=51; idty=0  lat:
sid=51; idty=0  lon:
sid=51; idty=0  alt:
-----------

:warning: supsicious is the second UPD_USR packet after the radios... :point_up:

hbeni commented 1 year ago

supsicious is the second UPD_USR packet after the radios... Resolved: The first one is the one from the generall notifier, the second one is the one by the detection of the changed internal plugin state. Not as clean as desired, but works-as-designed.

With a fresh restart of mumble, initial connection was established OK.

hbeni commented 1 year ago

The issue with the reconnecting to a already running mumble client: I think this might be an artifact when an mumble client has still established state. In this case there is no location change to the already-notified state, so the plugin will not notify again. The reason the Locstat is done asynchronously is that it changes often in-flight which will cause mass spam: https://github.com/hbeni/fgcom-mumble/blob/8c03be783c1791ec199c920a471152aadab78c37/client/mumble-plugin/lib/io_UDPServer.cpp#L688-L692

A solution could be that the statusbot looks into its state on ping packages, and if locstate is missing, ask for data.

hbeni commented 1 year ago

FGCom [2023-07-10 13:41:46.247]: [DBG] [GC] LCL searching for stale local state...
FGCom [2023-07-10 13:41:46.247]: [DBG] [GC] RMT searching for stale remote state...
FGCom [2023-07-10 13:41:46.546]: [DBG] [mum_pluginIO] fgcom_notifyThread() current locstate: iid=0
FGCom [2023-07-10 13:41:46.546]: [DBG] [mum_pluginIO] fgcom_notifyThread()   lcl.lat(48.344025)
FGCom [2023-07-10 13:41:46.547]: [DBG] [mum_pluginIO] fgcom_notifyThread()   lcl.lon(11.765083)
FGCom [2023-07-10 13:41:46.547]: [DBG] [mum_pluginIO] fgcom_notifyThread()   lcl.alt(-1.000000)
FGCom [2023-07-10 13:41:46.741]: [DBG] Internal state is as following:
---------LOCAL STATE-----------
plugin state: active
---------REMOTE STATE-----------

:lady_beetle: The local last notified state is not cleared when the IID is collected from the garbage collector.

hbeni commented 1 year ago

commit 306ec32 fixes the notification bug from the plugin that occurs when the udp connection is closed, the garbage collector erased the local state and then new local state is reestablished. If the location did not change significantly (as aircraft sitting idle, or ATC client), the location information was not shared to remote clients, leading to missing data.

hbeni commented 1 year ago

The last testing did not trigger that issue, and work has been done to fix related problems. I will close this for now. If it reappears, we may open again; until then we cross fingers that the recent commits were enough :crossed_fingers:

hbeni commented 1 year ago

Tested with a replay bot and could trigger the issue again: ./makeNDB.sh TEST --frq=0.342 --lat=47.839662 --lon=11.709538 --hgt=60 --ttl=172800

The bot was running for some time already and spawning a new replay bot resulted not in correct output of the status bot to the db.

Interestingly; the internal state of the statusbot was OK; something went wrong when generating the JSON output:

DATA INCOMING FROM=64
Received FGCOM-plugin data, dataID='FGCOM:PING', from=[64] 'FGCOM-RADIO-14972'
  data='0'
  datatype='FGCOM'
  packtype='PING'
ping packet for sid=64; iid=0
Parsing done. New remote state:
sid=64; idty=0    radio #0 frequency='0.342'
sid=64; idty=0    radio #0 dialedFRQ='0.342'
sid=64; idty=0    radio #0       ptt='1'
sid=64; idty=0    radio #0       pwr='10'
sid=64; idty=0    radio #0       opr='1'
sid=64; idty=0  type:   playback-bot
sid=64; idty=0  lastUpdate:     1689148522
sid=64; idty=0  callsign:       NDB:TEST
sid=64; idty=0  lat:    47.839662
sid=64; idty=0  lon:    11.709538
sid=64; idty=0  alt:    60
-----------
Update db '/home/beni/fgcom-web.db'
opened db '/home/beni/fgcom-web.db.part'
generateOutData(): number of known users: 0
generateOutData(): processing user: 64 with idty=0
  check frequency: radio #0, ptt='1', frq='0.342', dialedFRQ='0.342', operable=1
JSON RESULT: {"meta":{"highscore_clients":2, "highscore_date":1689057629}, "clients":[{"radios":{"0":{"srv":1, "dialedFRQ":"0.342"}}, "updated":1689148522}]}
wrote db '/home/beni/fgcom-web.db.part'
published db '/home/beni/fgcom-web.db'

Killing the statusbot and letting the botmanager spawn a fresh one was enough to fix it:

JSON RESULT: {"clients":[{"updated":1689149677, "alt":"60", "lon":"11.709538", "lat":"47.839662", "callsign":"NDB:TEST", "type":"playback-bot", "radios":{"0":{"dialedFRQ":"0.342", "srv":1, "operable":1, "pbt":1, "ptt":"1", "power":"10", "frequency":"0.342", "vlt":12}}}], "meta":{"highscore_date":1689057629, "highscore_clients":2}}

hbeni commented 1 year ago

So, after it ran a playback bot about the half day, we now get the following output: grafik

I already added debug code o we get a good output, but this i what the result is. Internal data still good, as we can see in the log. The JSON string is built from the hash from which the debug log is generated, so somehow the values get lost in the JSON module?

generateOutData(): processing user: 65 with idty=0
  check frequency: radio #0, ptt='1', frq='0.342', dialedFRQ='0.342', operable=1
  callsign=NDB:TEST
  type=playback-bot
  updated=1689192507
  lat=47.839662; lon=11.709538; alt=60
JSON RESULT: {"clients":[{"lat":"47.839662", "lon":"11.709538", "type":"playback-bot", "radios":{"0":{"ptt":"1", "operable":1}}, "updated":1689192507}], "meta":{"highscore_date":1689057629, "highscore_clients":2}}

hbeni commented 1 year ago

Maybe we should try http://dkolf.de/src/dkjson-lua.fsl/home?

Edit: Made that change in branch origin/Issue-168 and currently testing at the test server

hbeni commented 1 year ago

Looks good now wit the new json module.

Merged and closed.

hbeni commented 9 months ago

Related problem 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?

EDIT: Followup in #174

hbeni / fgcom-mumble

Bug: server/statubot starts to output missing/crippled database after some time #168