From d4c6cd94fea603b15864285597668c3240eee442 Mon Sep 17 00:00:00 2001 From: A_D Date: Sat, 22 Jan 2022 13:14:39 +0200 Subject: [PATCH 1/4] retry navroute parsing after failure --- monitor.py | 66 +++++++++++++++++++++++++++++++++++++++++++++++++----- 1 file changed, 60 insertions(+), 6 deletions(-) diff --git a/monitor.py b/monitor.py index ac3f55e1..01b70c74 100644 --- a/monitor.py +++ b/monitor.py @@ -10,7 +10,7 @@ from collections import OrderedDict, defaultdict from os import SEEK_END, SEEK_SET, listdir from os.path import basename, expanduser, isdir, join from sys import platform -from time import gmtime, localtime, sleep, strftime, strptime, time +from time import gmtime, localtime, mktime, sleep, strftime, strptime, time from typing import TYPE_CHECKING, Any, BinaryIO, Dict, List, MutableMapping, Optional from typing import OrderedDict as OrderedDictT from typing import Tuple @@ -23,8 +23,11 @@ from config import config from edmc_data import edmc_suit_shortnames, edmc_suit_symbol_localised from EDMCLogging import get_main_logger +# spell-checker: words navroute + logger = get_main_logger() STARTUP = 'journal.startup' +MAX_NAVROUTE_DISCREPANCY = 5 if TYPE_CHECKING: def _(x: str) -> str: @@ -111,6 +114,8 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below self.systempopulation: Optional[int] = None self.started: Optional[int] = None # Timestamp of the LoadGame event + self._navroute_retries = 0 + self.__init_state() def __init_state(self) -> None: @@ -167,6 +172,8 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below 'Dropship': None, # Best effort as to whether or not the above taxi is a dropship. 'Body': None, 'BodyType': None, + + 'NavRoute': None, } def start(self, root: 'tkinter.Tk') -> bool: # noqa: CCR001 @@ -494,6 +501,26 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below entry: MutableMapping[str, Any] = json.loads(line, object_pairs_hook=OrderedDict) entry['timestamp'] # we expect this to exist # TODO: replace with assert? or an if key in check + if self._navroute_retries > 0: + logger.debug(f'Navroute read retry [{self._navroute_retries}]') + self._navroute_retries -= 1 + nv_res = self._parse_navroute_file() + if ( + nv_res is None + or time() - mktime(strptime(nv_res['timestamp'], '%Y-%m-%dT%H:%M:%SZ')) > MAX_NAVROUTE_DISCREPANCY + ): + logger.debug( + 'Failed to parse navroute. ' + 'trying again...' if self._navroute_retries > 0 else 'Giving up' + ) + + if self._navroute_retries == 0: + self.state['NavRoute'] = None + + else: + self.state['NavRoute'] = nv_res + logger.debug('successfully read navroute file') + self._navroute_retries = 0 + event_type = entry['event'].lower() if event_type == 'fileheader': self.live = False @@ -1306,16 +1333,26 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below elif event_type == 'navroute': # Added in ED 3.7 - multi-hop route details in NavRoute.json - with open(join(self.currentdir, 'NavRoute.json'), 'rb') as rf: # type: ignore - try: - entry = json.load(rf) + if (nv_json := self._parse_navroute_file()) is not None: + entry_time = mktime(strptime(nv_json['timestamp'], '%Y-%m-%dT%H:%M:%SZ')) + c_time = time() - except json.JSONDecodeError: - logger.exception('Failed decoding NavRoute.json', exc_info=True) + if c_time - entry_time > MAX_NAVROUTE_DISCREPANCY: + logger.warning( + f'Parsed NavRoute.json timestamp is off by more than ' + f'{MAX_NAVROUTE_DISCREPANCY} ({c_time-entry_time=}).Trying again.' + ) + + self._navroute_retries = 10 else: + entry = nv_json self.state['NavRoute'] = entry + else: + logger.info('Failed to decode NavRoute.json. Trying again') + self._navroute_retries = 10 + elif event_type == 'moduleinfo': with open(join(self.currentdir, 'ModulesInfo.json'), 'rb') as mf: # type: ignore try: @@ -2157,6 +2194,23 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below return slots + def _parse_navroute_file(self) -> dict[str, Any] | None: + """Read and parse NavRoute.json.""" + if self.currentdir is None: + raise ValueError('currentdir unset') + + with open(join(self.currentdir, 'NavRoute.json'), 'r') as f: + raw = f.read() + + try: + data = json.loads(raw) + + except json.JSONDecodeError: + logger.exception('Failed to decode NavRoute.json', exc_info=True) + return None + + return data + # singleton monitor = EDLogs() From 06d4842da27b391b154e9b3c09a7ee7c4043f906 Mon Sep 17 00:00:00 2001 From: A_D Date: Tue, 25 Jan 2022 20:16:59 +0200 Subject: [PATCH 2/4] Be more parinoid about navroute files --- monitor.py | 40 ++++++++++++++++++++++++++++++---------- 1 file changed, 30 insertions(+), 10 deletions(-) diff --git a/monitor.py b/monitor.py index 01b70c74..231871b8 100644 --- a/monitor.py +++ b/monitor.py @@ -115,6 +115,7 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below self.started: Optional[int] = None # Timestamp of the LoadGame event self._navroute_retries = 0 + self._navroute_orig_time: Optional[float] = None self.__init_state() @@ -505,9 +506,13 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below logger.debug(f'Navroute read retry [{self._navroute_retries}]') self._navroute_retries -= 1 nv_res = self._parse_navroute_file() + if self._navroute_orig_time is None: + logger.critical('Asked to retry for navroute but also no set time to compare? This is a bug.') + if ( nv_res is None - or time() - mktime(strptime(nv_res['timestamp'], '%Y-%m-%dT%H:%M:%SZ')) > MAX_NAVROUTE_DISCREPANCY + or self._navroute_orig_time is None + or self._navroute_orig_time - self._parse_time(nv_res['timestamp']) > MAX_NAVROUTE_DISCREPANCY ): logger.debug( 'Failed to parse navroute. ' + 'trying again...' if self._navroute_retries > 0 else 'Giving up' @@ -520,6 +525,7 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below self.state['NavRoute'] = nv_res logger.debug('successfully read navroute file') self._navroute_retries = 0 + self._navroute_orig_time = None event_type = entry['event'].lower() if event_type == 'fileheader': @@ -1332,26 +1338,30 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below self.state['Taxi'] = False elif event_type == 'navroute': + # assume we've failed out the gate, then pull it back if things are fine + self._navroute_orig_time = mktime(strptime(entry['timestamp'], '%Y-%m-%dT%H:%M:%SZ')) + self._navroute_retries = 10 # Added in ED 3.7 - multi-hop route details in NavRoute.json - if (nv_json := self._parse_navroute_file()) is not None: - entry_time = mktime(strptime(nv_json['timestamp'], '%Y-%m-%dT%H:%M:%SZ')) - c_time = time() + if (nv_json := self._parse_navroute_file()) is not None and 'timestamp' in nv_json: + file_time = mktime(strptime(nv_json['timestamp'], '%Y-%m-%dT%H:%M:%SZ')) - if c_time - entry_time > MAX_NAVROUTE_DISCREPANCY: + if self._navroute_orig_time - file_time > MAX_NAVROUTE_DISCREPANCY: logger.warning( f'Parsed NavRoute.json timestamp is off by more than ' - f'{MAX_NAVROUTE_DISCREPANCY} ({c_time-entry_time=}).Trying again.' + f'{MAX_NAVROUTE_DISCREPANCY} ({self._navroute_orig_time-file_time=}).Trying again.' ) - self._navroute_retries = 10 - else: + # TODO: rather update entry here, overwriting existing fields but leaving others? + + # everything is happy, dont retry, dont set the original time, proceed as expected. entry = nv_json self.state['NavRoute'] = entry + self._navroute_retries = 0 + self._navroute_orig_time = None else: logger.info('Failed to decode NavRoute.json. Trying again') - self._navroute_retries = 10 elif event_type == 'moduleinfo': with open(join(self.currentdir, 'ModulesInfo.json'), 'rb') as mf: # type: ignore @@ -2194,11 +2204,14 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below return slots - def _parse_navroute_file(self) -> dict[str, Any] | None: + def _parse_navroute_file(self) -> Optional[dict[str, Any]]: """Read and parse NavRoute.json.""" if self.currentdir is None: raise ValueError('currentdir unset') + if not (pathlib.Path(self.currentdir) / 'NavRoute.json').exists(): + return None + with open(join(self.currentdir, 'NavRoute.json'), 'r') as f: raw = f.read() @@ -2209,8 +2222,15 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below logger.exception('Failed to decode NavRoute.json', exc_info=True) return None + if 'timestamp' not in data: # quick sanity check + return None + return data + @staticmethod + def _parse_time(source: str) -> float: + return mktime(strptime(source, '%Y-%m-%dT%H:%M:%SZ')) + # singleton monitor = EDLogs() From 36ecb69964d667570977170af62116005ae57ead Mon Sep 17 00:00:00 2001 From: A_D Date: Wed, 26 Jan 2022 13:17:27 +0200 Subject: [PATCH 3/4] refactor to use retry function for all attempts at navroute --- monitor.py | 97 ++++++++++++++++++++++++++++-------------------------- 1 file changed, 50 insertions(+), 47 deletions(-) diff --git a/monitor.py b/monitor.py index 231871b8..e01bfc41 100644 --- a/monitor.py +++ b/monitor.py @@ -502,30 +502,7 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below entry: MutableMapping[str, Any] = json.loads(line, object_pairs_hook=OrderedDict) entry['timestamp'] # we expect this to exist # TODO: replace with assert? or an if key in check - if self._navroute_retries > 0: - logger.debug(f'Navroute read retry [{self._navroute_retries}]') - self._navroute_retries -= 1 - nv_res = self._parse_navroute_file() - if self._navroute_orig_time is None: - logger.critical('Asked to retry for navroute but also no set time to compare? This is a bug.') - - if ( - nv_res is None - or self._navroute_orig_time is None - or self._navroute_orig_time - self._parse_time(nv_res['timestamp']) > MAX_NAVROUTE_DISCREPANCY - ): - logger.debug( - 'Failed to parse navroute. ' + 'trying again...' if self._navroute_retries > 0 else 'Giving up' - ) - - if self._navroute_retries == 0: - self.state['NavRoute'] = None - - else: - self.state['NavRoute'] = nv_res - logger.debug('successfully read navroute file') - self._navroute_retries = 0 - self._navroute_orig_time = None + self.__navroute_retry() event_type = entry['event'].lower() if event_type == 'fileheader': @@ -1340,28 +1317,12 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below elif event_type == 'navroute': # assume we've failed out the gate, then pull it back if things are fine self._navroute_orig_time = mktime(strptime(entry['timestamp'], '%Y-%m-%dT%H:%M:%SZ')) - self._navroute_retries = 10 + self._navroute_retries = 11 + # Added in ED 3.7 - multi-hop route details in NavRoute.json - if (nv_json := self._parse_navroute_file()) is not None and 'timestamp' in nv_json: - file_time = mktime(strptime(nv_json['timestamp'], '%Y-%m-%dT%H:%M:%SZ')) - - if self._navroute_orig_time - file_time > MAX_NAVROUTE_DISCREPANCY: - logger.warning( - f'Parsed NavRoute.json timestamp is off by more than ' - f'{MAX_NAVROUTE_DISCREPANCY} ({self._navroute_orig_time-file_time=}).Trying again.' - ) - - else: - # TODO: rather update entry here, overwriting existing fields but leaving others? - - # everything is happy, dont retry, dont set the original time, proceed as expected. - entry = nv_json - self.state['NavRoute'] = entry - self._navroute_retries = 0 - self._navroute_orig_time = None - - else: - logger.info('Failed to decode NavRoute.json. Trying again') + # rather than duplicating this, lets just call the function + if self.__navroute_retry(): + entry = self.state['NavRoute'] elif event_type == 'moduleinfo': with open(join(self.currentdir, 'ModulesInfo.json'), 'rb') as mf: # type: ignore @@ -2212,8 +2173,14 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below if not (pathlib.Path(self.currentdir) / 'NavRoute.json').exists(): return None - with open(join(self.currentdir, 'NavRoute.json'), 'r') as f: - raw = f.read() + try: + + with open(join(self.currentdir, 'NavRoute.json'), 'r') as f: + raw = f.read() + + except Exception as e: + logger.exception(f'Could not open navroute file. Bailing: {e}') + return None try: data = json.loads(raw) @@ -2231,6 +2198,42 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below def _parse_time(source: str) -> float: return mktime(strptime(source, '%Y-%m-%dT%H:%M:%SZ')) + def __navroute_retry(self) -> bool: + """Retry reading navroute files.""" + if self._navroute_retries == 0: + return False + + logger.info(f'Navroute read retry [{self._navroute_retries}]') + self._navroute_retries -= 1 + + if self._navroute_orig_time is None: + logger.critical('Asked to retry for navroute but also no set time to compare? This is a bug.') + return False + + if (file := self._parse_navroute_file()) is None: + logger.debug( + 'Failed to parse NavRoute.json. ' + + ('Trying again' if self._navroute_retries > 0 else 'Giving up') + ) + return False + + # _parse_navroute_file verifies that this exists for us + file_time = self._parse_time(file['timestamp']) + if abs(file_time - self._navroute_orig_time) > MAX_NAVROUTE_DISCREPANCY: + logger.debug( + f'Time discrepancy of more than {MAX_NAVROUTE_DISCREPANCY}s --' + f' ({abs(file_time - self._navroute_orig_time)}).' + f' {"Trying again" if self._navroute_retries > 0 else "Giving up"}.' + ) + return False + + # everything is good, lets set what we need to and make sure we dont try again + logger.info('Successfully read NavRoute file for last NavRoute event.') + self.state['NavRoute'] = file + self._navroute_retries = 0 + self._navroute_orig_time = None + return True + # singleton monitor = EDLogs() From 62a0a96dc646863bd0ea01e8f0419b4a581ba690 Mon Sep 17 00:00:00 2001 From: A_D Date: Wed, 26 Jan 2022 17:42:50 +0200 Subject: [PATCH 4/4] resolve final review comments --- monitor.py | 35 ++++++++++++++++------------------- 1 file changed, 16 insertions(+), 19 deletions(-) diff --git a/monitor.py b/monitor.py index e01bfc41..f5e9a3ac 100644 --- a/monitor.py +++ b/monitor.py @@ -114,8 +114,8 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below self.systempopulation: Optional[int] = None self.started: Optional[int] = None # Timestamp of the LoadGame event - self._navroute_retries = 0 - self._navroute_orig_time: Optional[float] = None + self._navroute_retries_remaining = 0 + self._last_navroute_journal_timestamp: Optional[float] = None self.__init_state() @@ -1316,8 +1316,8 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below elif event_type == 'navroute': # assume we've failed out the gate, then pull it back if things are fine - self._navroute_orig_time = mktime(strptime(entry['timestamp'], '%Y-%m-%dT%H:%M:%SZ')) - self._navroute_retries = 11 + self._last_navroute_journal_timestamp = mktime(strptime(entry['timestamp'], '%Y-%m-%dT%H:%M:%SZ')) + self._navroute_retries_remaining = 11 # Added in ED 3.7 - multi-hop route details in NavRoute.json # rather than duplicating this, lets just call the function @@ -2170,9 +2170,6 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below if self.currentdir is None: raise ValueError('currentdir unset') - if not (pathlib.Path(self.currentdir) / 'NavRoute.json').exists(): - return None - try: with open(join(self.currentdir, 'NavRoute.json'), 'r') as f: @@ -2195,43 +2192,43 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below return data @staticmethod - def _parse_time(source: str) -> float: + def _parse_journal_timestamp(source: str) -> float: return mktime(strptime(source, '%Y-%m-%dT%H:%M:%SZ')) def __navroute_retry(self) -> bool: """Retry reading navroute files.""" - if self._navroute_retries == 0: + if self._navroute_retries_remaining == 0: return False - logger.info(f'Navroute read retry [{self._navroute_retries}]') - self._navroute_retries -= 1 + logger.info(f'Navroute read retry [{self._navroute_retries_remaining}]') + self._navroute_retries_remaining -= 1 - if self._navroute_orig_time is None: + if self._last_navroute_journal_timestamp is None: logger.critical('Asked to retry for navroute but also no set time to compare? This is a bug.') return False if (file := self._parse_navroute_file()) is None: logger.debug( 'Failed to parse NavRoute.json. ' - + ('Trying again' if self._navroute_retries > 0 else 'Giving up') + + ('Trying again' if self._navroute_retries_remaining > 0 else 'Giving up') ) return False # _parse_navroute_file verifies that this exists for us - file_time = self._parse_time(file['timestamp']) - if abs(file_time - self._navroute_orig_time) > MAX_NAVROUTE_DISCREPANCY: + file_time = self._parse_journal_timestamp(file['timestamp']) + if abs(file_time - self._last_navroute_journal_timestamp) > MAX_NAVROUTE_DISCREPANCY: logger.debug( f'Time discrepancy of more than {MAX_NAVROUTE_DISCREPANCY}s --' - f' ({abs(file_time - self._navroute_orig_time)}).' - f' {"Trying again" if self._navroute_retries > 0 else "Giving up"}.' + f' ({abs(file_time - self._last_navroute_journal_timestamp)}).' + f' {"Trying again" if self._navroute_retries_remaining > 0 else "Giving up"}.' ) return False # everything is good, lets set what we need to and make sure we dont try again logger.info('Successfully read NavRoute file for last NavRoute event.') self.state['NavRoute'] = file - self._navroute_retries = 0 - self._navroute_orig_time = None + self._navroute_retries_remaining = 0 + self._last_navroute_journal_timestamp = None return True