Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

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

Closed
2 tasks done
hbeni opened this issue Jul 10, 2023 · 14 comments
Closed
2 tasks done
Assignees
Labels
bug Something isn't working mumble-plugin Affecting mumble plugin Status Page Affecting the status page implementation
Milestone

Comments

@hbeni
Copy link
Owner

hbeni commented Jul 10, 2023

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:

  • 🐞 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 ✔️ )
    => (as fallback, low prio ⬇️) Statusbot needs to reask for missing state on incoming PING packages
  • Database missing info with long running statusbot and fresh connections (comment: reproduce info)
    => JSON lua module seemed to be the cause
@hbeni hbeni added the bug Something isn't working label Jul 10, 2023
@hbeni
Copy link
Owner Author

hbeni commented Jul 10, 2023

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
Copy link
Owner Author

hbeni commented Jul 10, 2023

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 hbeni self-assigned this Jul 10, 2023
@hbeni hbeni added mumble-plugin Affecting mumble plugin Status Page Affecting the status page implementation labels Jul 10, 2023
@hbeni
Copy link
Owner Author

hbeni commented Jul 10, 2023

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
Copy link
Owner Author

hbeni commented Jul 10, 2023

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:
-----------

⚠️ supsicious is the second UPD_USR packet after the radios... ☝️

@hbeni
Copy link
Owner Author

hbeni commented Jul 10, 2023

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
Copy link
Owner Author

hbeni commented Jul 10, 2023

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:

// If we got locationdata changed, do NOT notify. This is handled asynchronusly from the notify thread.
/*if (ures.locationData) {
pluginDbg("[UDP-server] locationData for iid='"+std::to_string(iid)+"' has changed, notifying other clients");
notifyRemotes(iid, 1);
}*/

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

@hbeni
Copy link
Owner Author

hbeni commented Jul 10, 2023

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-----------

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

hbeni added a commit that referenced this issue Jul 10, 2023
So reestablishing udp connections will transmit location data again.
This is a solution to #168
@hbeni
Copy link
Owner Author

hbeni commented Jul 10, 2023

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 hbeni added this to the Next milestone Jul 11, 2023
@hbeni
Copy link
Owner Author

hbeni commented Jul 11, 2023

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
🤞

@hbeni hbeni closed this as completed Jul 11, 2023
@hbeni
Copy link
Owner Author

hbeni commented Jul 12, 2023

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 hbeni reopened this Jul 12, 2023
@hbeni
Copy link
Owner Author

hbeni commented Jul 12, 2023

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
Copy link
Owner Author

hbeni commented Jul 12, 2023

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
Copy link
Owner Author

hbeni commented Jul 14, 2023

Looks good now wit the new json module.

Merged and closed.

@hbeni hbeni closed this as completed Jul 14, 2023
@hbeni hbeni reopened this Feb 16, 2024
@hbeni
Copy link
Owner Author

hbeni commented Feb 16, 2024

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).

👀 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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working mumble-plugin Affecting mumble plugin Status Page Affecting the status page implementation
Projects
None yet
Development

No branches or pull requests

1 participant