clue dialog closure errors

caver456 commented 1 year ago

Unusual entries and dialog closure issues when accepting a clue dialog, noticed in 3.6.1 on 5-21-23:

20230521_150840

Accompanied by these lines in the log file:

134632:newEntry called with these values:
134632:['1343', 'FROM', 'Team 101', 'RADIO LOG SOFTWARE: CLUE REPORT OPENED BUT CANCELED BY THE OPERATOR.  CLUE REPORT DATA BEFORE CANCELATION: DESCRIPTION="fake cardboard bloody knife" LOCATION="92861 53231" INSTRUCTIONS="MARK & LEAVE; PHOTOGRAPH; CONTINUE SEARCH" ', '92864  53237', 'Working', 1684701806.231355, '100', '3035', '3918.4232|N|12045.7882|W']
Uncaught exception
Traceback (most recent call last):
  File "radiolog.py", line 6924, in closeEvent
ValueError: list.remove(x): x not in list

Other occurrences have more error lines - it looks like this problem was plaguing the operators all day:

112745:generating clue report pdf: C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803_clue01.pdf
112748:accepted - calling close
Uncaught exception
Traceback (most recent call last):
  File "radiolog.py", line 6871, in accept
  File "radiolog.py", line 6924, in closeEvent
ValueError: list.remove(x): x not in list
112755:Accepted
112755:newEntry called with these values:
112755:['1125', 'FROM', 'Team 103', 'CLUE#1: 1X1 BLUE MATERIAL, RIP STOP IN DEEP BRUSH ; LOCATION: 92670 X 53305; INSTRUCTIONS: MRK ON GPS AND PROCEED W/ASSIGNMENT; CLUE#1: 1X1 BLUE MATERIAL, RIP STOP IN DEEP BRUSH ; LOCATION: 92670 X 53305; INSTRUCTIONS: MRK ON GPS AND PROCEED W/ASSIGNMENT', '92662  53299', 'Working', 1684693522.5658386, '100', '4007', '3918.4596|N|12045.9276|W']
112755:Accepted2
112755:  writing C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803.csv
112755:  done writing C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803.csv
112755:  writing X:\Chalk_Bluff_2023_05_21_081803.csv
112755:  done writing X:\Chalk_Bluff_2023_05_21_081803.csv
112755:  writing C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803_clueLog.csv
112755:  done writing C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803_clueLog.csv
112755:  writing X:\Chalk_Bluff_2023_05_21_081803_clueLog.csv
112756:  done writing X:\Chalk_Bluff_2023_05_21_081803_clueLog.csv
112813:vText:
112813:generating clue report pdf: C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803_clue01.pdf
112813:parsed instructions:['mrk on gps and proceed w/assignment']
112813:copying clue report pdf to X:\
112813:accepted - calling close
Uncaught exception
Traceback (most recent call last):
  File "radiolog.py", line 6871, in accept
  File "radiolog.py", line 6924, in closeEvent
ValueError: list.remove(x): x not in list
112814:vText:
112814:generating clue report pdf: C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803_clue01.pdf
112818:accepted - calling close
Uncaught exception
Traceback (most recent call last):
  File "radiolog.py", line 6871, in accept
  File "radiolog.py", line 6924, in closeEvent
ValueError: list.remove(x): x not in list
112843:vText:
112843:generating clue report pdf: C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803_clue01.pdf
112843:parsed instructions:['mrk on gps and proceed w/assignment']
112843:copying clue report pdf to X:\
112843:accepted - calling close
Uncaught exception
Traceback (most recent call last):
  File "radiolog.py", line 6871, in accept
  File "radiolog.py", line 6924, in closeEvent
ValueError: list.remove(x): x not in list
112844:vText:
112844:generating clue report pdf: C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803_clue01.pdf
112854:accepted - calling close
Uncaught exception
Traceback (most recent call last):
  File "radiolog.py", line 6871, in accept
  File "radiolog.py", line 6924, in closeEvent
ValueError: list.remove(x): x not in list
112907:newEntry called with these values:
112907:['1125', 'FROM', 'Team 103', 'RADIO LOG SOFTWARE: CLUE REPORT OPENED BUT CANCELED BY THE OPERATOR.  CLUE REPORT DATA BEFORE CANCELATION: DESCRIPTION="1X1 BLUE MATERIAL, RIP STOP IN DEEP BRUSH " LOCATION="92670 X 53305" INSTRUCTIONS="MRK ON GPS AND PROCEED W/ASSIGNMENT" ', '92662  53299', 'Working', 1684693522.5658386, '100', '4007', '3918.4596|N|12045.9276|W']
Uncaught exception
Traceback (most recent call last):
  File "radiolog.py", line 6924, in closeEvent
ValueError: list.remove(x): x not in list

caver456 commented 1 year ago

notes from reading through the log file:

the error on 6924 is from this code inside clueDialog.closeEvent: self.parent.childDialogs.remove(self) so the dialog in question is just not in its parent's childDialogs list. Can easily check for this case to prevent the exception, but, the exception is probably just a symptom of the fact that newEntryWidget.childDialogs is out of sync for some reason
the line pair '6871 accept / 6924 closeEvent' happens when the dialog is accepted; the single line on its own '6924 closeEvent' probably happens when the dialog is canceled
the first occurrance of the line pair happens at 112748. For the same clue, 4 seconds prior at 112744, 'accepted - calling close / Accepted' is in the log with no traceback. Maybe this is a case of OK being clicked a second time before the clue dialog actually closes?

caver456 commented 1 year ago

Here's the entire log section of the first occurrance, starting with the successful close, through to the message at the end of the second close with the error message. Maybe the failed rotateCsvBackups is causing the problem - notice that 6871 / 6927 in the traceback are in the same section of code, triggered when the clue dialog is accepted:

112744:accepted - calling close
112744:Accepted
112744:newEntry called with these values:
112744:['1125', 'FROM', 'Team 103', 'CLUE#1: 1X1 BLUE MATERIAL, RIP STOP IN DEEP BRUSH ; LOCATION: 92670 X 53305; INSTRUCTIONS: MRK ON GPS AND PROCEED W/ASSIGNMENT', '92662  53299', 'Working', 1684693522.5658386, '100', '4007', '3918.4596|N|12045.9276|W']
112744:Invoking backup rotation script (with arguments): ['', 'C:\\Users\\NCSSAR\\RadioLog\\Chalk_Bluff_2023_05_21_081803\\Chalk_Bluff_2023_05_21_081803.csv', 'C:\\Users\\NCSSAR\\RadioLog\\Chalk_Bluff_2023_05_21_081803\\Chalk_Bluff_2023_05_21_081803_clueLog.csv', 'C:\\Users\\NCSSAR\\RadioLog\\Chalk_Bluff_2023_05_21_081803\\radiolog_fleetsync.csv', 'X:\\Chalk_Bluff_2023_05_21_081803.csv', 'X:\\Chalk_Bluff_2023_05_21_081803_clueLog.csv', 'X:\\radiolog_fleetsync.csv']
Uncaught exception
Traceback (most recent call last):
  File "radiolog.py", line 6871, in accept
  File "radiolog.py", line 6927, in closeEvent
  File "radiolog.py", line 6210, in accept
  File "radiolog.py", line 1539, in rotateCsvBackups
  File "subprocess.py", line 971, in __init__
  File "subprocess.py", line 1440, in _execute_child
OSError: [WinError 87] The parameter is incorrect
112744:  writing C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803.csv
112744:  done writing C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803.csv
112744:  writing X:\Chalk_Bluff_2023_05_21_081803.csv
112744:  done writing X:\Chalk_Bluff_2023_05_21_081803.csv
112744:  writing C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803_clueLog.csv
112744:  done writing C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803_clueLog.csv
112744:  writing X:\Chalk_Bluff_2023_05_21_081803_clueLog.csv
112744:  done writing X:\Chalk_Bluff_2023_05_21_081803_clueLog.csv
112745:vText:
112745:generating clue report pdf: C:\Users\NCSSAR\RadioLog\Chalk_Bluff_2023_05_21_081803\Chalk_Bluff_2023_05_21_081803_clue01.pdf
112748:accepted - calling close
Uncaught exception
Traceback (most recent call last):
  File "radiolog.py", line 6871, in accept
  File "radiolog.py", line 6924, in closeEvent
ValueError: list.remove(x): x not in list
112755:Accepted
112755:newEntry called with these values:
112755:['1125', 'FROM', 'Team 103', 'CLUE#1: 1X1 BLUE MATERIAL, RIP STOP IN DEEP BRUSH ; LOCATION: 92670 X 53305; INSTRUCTIONS: MRK ON GPS AND PROCEED W/ASSIGNMENT; CLUE#1: 1X1 BLUE MATERIAL, RIP STOP IN DEEP BRUSH ; LOCATION: 92670 X 53305; INSTRUCTIONS: MRK ON GPS AND PROCEED W/ASSIGNMENT', '92662  53299', 'Working', 1684693522.5658386, '100', '4007', '3918.4596|N|12045.9276|W']
112755:Accepted2

caver456 commented 1 year ago

bingo - the theory was right - the error during rotate causes the dialog to be left open; hitting OK again triggers the error pair line.

So this should be a two-part solution: 1) solve #650 so that an error in the backup script doesn't leave the clue dialog open; 2) check for existence of self in self.parent.childDialogs before removing, to prevent the error lines in question - though this is mainly cosmetic

caver456 commented 1 year ago

for reference: the error was duplicated by setting rotateScript='' in radiolog.cfg, then adding a clue as the 5th saved entry so that the rotate script was called during accept of the clue dialog.

caver456 commented 1 year ago

rethinking - skipping part 2 of the solution, since there are apparently no downstream effects from these uncaught exceptions, and they serve as good indicators in the log file that childDialogs is out of sync. With #650 being fixed, there >should< be no other case where these exceptions happen.

ncssar / radiolog

clue dialog closure errors #651