apparent hold time failure in 3.11.1

[caver456]

Observed at K9 training 1-27-24, initially couldn't reproduce at home with fsTester, but then modified fsTester to not start sending until after the end of one delay interval, which made it reproducible. Still need to confirm at the command vehicle (with actual radios), but, reproducibility at home gives good enough confidence to call this a critical bug.

[caver456]

When the new (interrupting) transmission comes in, the new tab gets added on the stack but does not activate. No change-callsign dialog appears, but, the message field of the existing message loses focus (the cursor disappears). It's not clear exactly what steals the focus. The next keystroke appears to change the callsign field of the existing message, but, the callsign text of the inactive newest message stack tab is what actually changes as you type.

[caver456]

Here's the transcript clause starting with the interrupting transmission from 5003 - note that a second new entry tab is created on EOT, even though EOT happens 1.5 seconds after BOT:

060930:PARSING
060930:☻I110050031005003♥
060930: line:☻I110050031005003♥
060930:getCallsign called for FleetSync fleet=100 dev=5003
060930:  no matches
060930:FleetSync CID detected (not in $PKLSH): fleet=100  dev=5003  callsign=KW-100-5003
060930:checking for existing open new entry tabs: callsign=KW-100-5003 continueSec=20
060930:checking against existing widget: to_from=FROM team=Team 1 lastModAge:2
060930:updating fsLog (fleetsync): fleet=100 dev=5003 callsign=<None>  COM port=COM2
060930:getCallsign called for FleetSync fleet=100 dev=5003
060930:  no matches
060930:no other new entry tab was found for this callsign; inside fsParse: calling openNewEntry
060930:openNewEntry called:key=fs callsign=KW-100-5003 formattedLocString= fleet=100 dev=5003 origLocString= amendFlag=False amendRow=None isMostRecentForCallsign=False
060930:newEntryWidget __init__ called: formattedLocString= fleet=100 dev=5003 origLocString= amendFlag=False amendRow=None isMostRecentForCallsign=False
060930:newEntryWidget.addTab called: labelText=0609  widget=<__main__.newEntryWidget object at 0x000001E39C1D3EB0>
060930:inserting tab
060930:First non-mic-bump call from this device.
060930:Setting needsChangeCallsign since this is the first call from the device and the beginning of its default callsign "KW-100-5003" is specified in CCD1List
060932:PARSING
060932:☻I010050031005003♥
060932: line:☻I010050031005003♥
060932:getCallsign called for FleetSync fleet=100 dev=5003
060932:  no matches
060932:FleetSync CID detected (not in $PKLSH): fleet=100  dev=5003  callsign=KW-100-5003
060932:checking for existing open new entry tabs: callsign=KW-100-5003 continueSec=20
060932:checking against existing widget: to_from=FROM team=Team 1 lastModAge:4
060932:checking against existing widget: to_from=FROM team=sd lastModAge:-1
060932:updating fsLog (fleetsync): fleet=100 dev=5003 callsign=<None>  COM port=COM2
060932:no other new entry tab was found for this callsign; inside fsParse: calling openNewEntry
060932:openNewEntry called:key=fs callsign=KW-100-5003 formattedLocString= fleet=100 dev=5003 origLocString= amendFlag=False amendRow=None isMostRecentForCallsign=False
060932:newEntryWidget __init__ called: formattedLocString= fleet=100 dev=5003 origLocString= amendFlag=False amendRow=None isMostRecentForCallsign=False
060932:newEntryWidget.addTab called: labelText=0609  widget=<__main__.newEntryWidget object at 0x000001E39C1D7760>
060932:inserting tab
060932:First non-mic-bump call from this device.
060932:Setting needsChangeCallsign since this is the first call from the device and the beginning of its default callsign "KW-100-5003" is specified in CCD1List

[caver456]

3.10.2 exhibits the same problem.

3.6.1 doesn't have the problem, and looks like it's functioning correctly, as much as I can tell from home; but, the message field of the existing message does lose focus, which has always been a side-effect of using the fleetsync emulator, which steals Windows-level focus in order to send the emulated transmission.

This does point out that confirmation with the real mobile radio is still needed, but, for now we can say the bug was introduced after 3.6.1 and before 3.10.2.

[caver456]

3.8.0 and 3.9.0 are good, so, the error was introduced for 3.10.2. Here's the transcript from 3.9.0 for an interrupting incoming FS call:

064512:     DATA IS WAITING!!!
064512:      VALID FLEETSYNC DATA!!!
064512:PARSING
064512:☻I110050011005001♥
064512: line:☻I110050011005001♥
064512:getCallsign called for FleetSync fleet=100 dev=5001
064512:  no matches
064512:FleetSync CID detected (not in $PKLSH): fleet=100  dev=5001  callsign=KW-100-5001
064512:checking for existing open new entry tabs: callsign=KW-100-5001 continueSec=20
064512:checking against existing widget: to_from=FROM team=Team 1 lastModAge:3
064512:updating fsLog (fleetsync): fleet=100 dev=5001 callsign=<None>  COM port=COM2
064512:getCallsign called for FleetSync fleet=100 dev=5001
064512:  no matches
064512:no other new entry tab was found for this callsign; inside fsParse: calling openNewEntry
064512:openNewEntry called:key=fs callsign=KW-100-5001 formattedLocString= fleet=100 dev=5001 origLocString= amendFlag=False amendRow=None isMostRecentForCallsign=False
064512:newEntryWidget __init__ called: formattedLocString= fleet=100 dev=5001 origLocString= amendFlag=False amendRow=None isMostRecentForCallsign=False
064512:newEntryWidget.addTab called: labelText=0645  widget=<__main__.newEntryWidget object at 0x0000027F5EDAA710>
064512:inserting tab
064512:First non-mic-bump call from this device.
064512:Setting needsChangeCallsign since this is the first call from the device and the beginning of its default callsign "KW-100-5001" is specified in CCD1List
064514:PARSING
064514:☻I010050011005001♥
064514: line:☻I010050011005001♥
064514:getCallsign called for FleetSync fleet=100 dev=5001
064514:  no matches
064514:FleetSync CID detected (not in $PKLSH): fleet=100  dev=5001  callsign=KW-100-5001
064514:checking for existing open new entry tabs: callsign=KW-100-5001 continueSec=20
064514:checking against existing widget: to_from=FROM team=Team 1 lastModAge:5
064514:checking against existing widget: to_from=FROM team=KW-100-5001 lastModAge:0
064514:  new entry widget is already open from this callsign within the 'continue time'; not opening a new one
064514:location strings updated because the message is not relayed
064514:updating fsLog (fleetsync): fleet=100 dev=5001 callsign=<None>  COM port=COM2

[caver456]

Comparing the transcript sections, the second new entry tab (on EOT) is a follow-on result of the underlying error - the callsign having changed between BOT and EOT due to captured keystrokes modifying the callsign of the BOT call. But, there are no other indications in the transcript as to why the focus got stolen. So - digging into code differences between 3.9.0 and 3.10.2 of which there are many...

[caver456]

Did a binary test of downloaded zip files of repos at each commit between 3.9.0 and 3.10.2. Based on that, the error was introduced in https://github.com/ncssar/radiolog/commit/87459105d790af3c7c24d68a3151742451facc4e - but the changes are tiny, only related to Window Flags. It raises the question of whether this error is inconsistent, but repeated testing with #b4a79e9 ('fix #670') is OK (doesn't display the error) and repeated testing with #8775910 ('fix #671') is BAD (does display the error).

[caver456]

Apparently, the thing that causes the problem is failure to set the window flags on every call to openNewEntry, even if the flag values didn't change. This is really the only change that was made in that commit, so, seems like #671 needs a different fix.

Looking at the window flags before and efter each call to openNewEntry, there seems to be no difference in either case (setting the flags every time, or, only setting if the flags had changed in some other manner). In all cases, the flags are WindowTitleHint, SystemMenuHint, and StaysOnTopHint. FramelessWindowHint gets clobbered during init, which seems to be OK.

[caver456]

Changing to setWindowFlag(singular) instead of setWindowFlags(plural), on every call to openNewEntry rather than only calling if there was a change, also causes the same problem:

        x=True
        if clueDialog.openDialogCount>0:
            # self.NEWFlags=Qt.WindowTitleHint|Qt.WindowStaysOnTopHint
            x=False
        self.newEntryWindow.setWindowFlag(Qt.WindowStaysOnTopHint,x)

so the mystery continues. The nuclear option is to un-fix #671 but that would be a bummer.

[caver456]

Fixed in code yesterday from the R6 computer. Adding some notes after the fact:

Turns out that all of the #671 code was commented out during #16a533b "WIP - simplify StaysOnTop behavior" Sep 23 2023. So, in 3.10.2 and 3.11.1, setFlags was never getting called (after init). Looking elsewhere, this code, and the comment a bit farther down, seemed relevant:

...
        if callsign:
            extTeamName=getExtTeamName(callsign)
            self.newEntryWidget.ui.teamField.setText(callsign)
            self.newEntryWidget.teamFieldEditingFinished() # check for relay
            if callsign[0:3]=='KW-':
                self.newEntryWidget.ui.teamField.setFocus()
                self.newEntryWidget.ui.teamField.selectAll()
...
                    # note that changeCallsignDialog.accept is responsible for
                    #  setting focus back to the messageField of the active message
                    #  (not always the same as the new message)
...

Looks like that 'if callsign[0:3]' clause was written without considering that the new widget might not be the active widget. So - here's the fix:

            #726 - don't steal focus to the callsign field unless it's also the active widget
            # if callsign[0:3]=='KW-':
            if callsign[0:3]=='KW-' and self.newEntryWidget==self.newEntryWindow.ui.tabWidget.currentWidget():

But it also means that the focus-stealing only happened if the new message didn't have a default callsign other than KW-... and also that this focus-stealing-for-KW- has been in place for a lot longer than Sep 2023! Confirmed that the stealing-for-KW was in place on 3.9.0. Normally this is never the case since there are default callsigns (SAR # or Radio #) from the default callsign file .config/radiolog_fleetsync.csv. But: radiolog.csv from the R6 run dir at the training where this bug was discovered only has one dummy entry:

Normally, radiolog_fleetsync.csv in the run dir is the 'evaluated' starting point (after evaluation of the ranges-syntax in .config/radiolog_fleetsync.csv).

So, presumably, .config/radiolog_fleetsync.csv is missing from the R6 install...

The final .csv in the run dir looks better, but, guessing these associations were all entered by hand

and, sure enough, in the transcript, all of the initial getCallsign calls (e.g. for 100:3108 which should be 'SAR 108') returned with 'no matches' meaning they would get KW-...

Anyway - all looks good in 3.13.3. This makes sense with earlier notes indicating that the loss of focus might have been expected dur to fsTester: the only time it should lose focus is if there's a GUI interaction with the fsTester window - but all these tests were done using the interval-send feature of fsTester, so, that noted expectation was wrong.

Summing up:

1) this fix actually fixed a problem that was around for much longer, but, was probably never seen on a search due to the initial callsign correspondences in .config/radiolog_fleetsync.csv 2) looks like .config/radiolog_fleetsync.csv may be missing from R6. This is expected behavior, since radiolog_fleetsync.csv is team-specific therefore is not part of the radiolog installation - but, looks like it was never put into place after the initial installation (so other .config items may be missing too). 3) confirmed with fsTester (not with a real radio) that 3.13.3 doesn't steal focus or lose focus, regardless of whether the new call is KW-* (e.g. a device that's not in the initial radiolog_fleetsync.csv) or whether it does have a default callsign.