From 3afcac0dea5bf513a32e99069e2a7ea16954442a Mon Sep 17 00:00:00 2001 From: Athanasius Date: Tue, 22 Sep 2020 18:49:07 +0100 Subject: [PATCH 1/2] monitor.py: Use logging for Journal Folder/File announcements --- monitor.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/monitor.py b/monitor.py index e1fbf037..1f0da2ed 100644 --- a/monitor.py +++ b/monitor.py @@ -2,7 +2,6 @@ from collections import defaultdict, OrderedDict import json import re import threading -from operator import itemgetter from os import listdir, SEEK_SET, SEEK_END from os.path import basename, expanduser, isdir, join from sys import platform @@ -18,7 +17,9 @@ if __debug__: from config import config from companion import ship_file_name +from EDMCLogging import get_main_logger +logger = get_main_logger() if platform == 'darwin': from AppKit import NSWorkspace @@ -173,9 +174,8 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below if not self.observed and not polling: self.observed = self.observer.schedule(self, self.currentdir) - if __debug__: - print('{} Journal {!r}'.format('Polling' if polling else 'Monitoring', self.currentdir)) - print('Start logfile {!r}'.format(self.logfile)) + logger.info(f'{"Polling" if polling else "Monitoring"} Journal Folder: {self.currentdir}') + logger.info(f'Start Journal File: {self.logfile}') if not self.running(): self.thread = threading.Thread(target=self.worker, name='Journal worker') From 85d45aadd767a64d252d23d5d9a17ac584e32c8b Mon Sep 17 00:00:00 2001 From: Athanasius Date: Wed, 23 Sep 2020 11:45:48 +0100 Subject: [PATCH 2/2] Place detailed logging for "Location" events. To try and track down what's happening with #713 --- EDMarketConnector.py | 11 +++++++- companion.py | 2 +- monitor.py | 66 ++++++++++++++++++++++++++++---------------- plug.py | 3 ++ plugins/edsm.py | 17 ++++++++++-- 5 files changed, 71 insertions(+), 28 deletions(-) diff --git a/EDMarketConnector.py b/EDMarketConnector.py index ccfac5fe..5cc7aff5 100755 --- a/EDMarketConnector.py +++ b/EDMarketConnector.py @@ -602,7 +602,13 @@ class AppWindow(object): pass # Handle event(s) from the journal - def journal_event(self, event): + def journal_event(self, event: str): + """ + Handle a Journal event passed through event queue from monitor.py. + + :param event: string JSON data of the event + :return: + """ def crewroletext(role): # Return translated crew role. Needs to be dynamic to allow for changing language. @@ -617,6 +623,7 @@ class AppWindow(object): while True: entry = monitor.get_entry() if not entry: + logger.debug('No entry from monitor.get_entry()') return # Update main window @@ -668,9 +675,11 @@ class AppWindow(object): self.login() if not entry['event'] or not monitor.mode: + logger.debug('Startup or in CQC, returning') return # Startup or in CQC if entry['event'] in ['StartUp', 'LoadGame'] and monitor.started: + logger.info('Startup or LoadGame event') # Disable WinSparkle automatic update checks, IFF configured to do so when in-game if config.getint('disable_autoappupdatecheckingame') and 1: self.updater.setAutomaticUpdatesCheck(False) diff --git a/companion.py b/companion.py index ee6369eb..f52724b7 100644 --- a/companion.py +++ b/companion.py @@ -405,7 +405,7 @@ class Session(object): else: credentials = {'cmdr': cmdr, 'beta': is_beta} if self.credentials == credentials and self.state == Session.STATE_OK: - logger.debug('already logged in (is_beta)') + logger.debug(f'already logged in (is_beta = {is_beta})') return True # already logged in else: diff --git a/monitor.py b/monitor.py index 1f0da2ed..e2f2105c 100644 --- a/monitor.py +++ b/monitor.py @@ -7,14 +7,11 @@ from os.path import basename, expanduser, isdir, join from sys import platform from time import gmtime, localtime, sleep, strftime, strptime, time from calendar import timegm -from typing import Any, Optional, OrderedDict as OrderedDictT, Tuple, TYPE_CHECKING +from typing import Any, Optional, OrderedDict as OrderedDictT, Tuple, TYPE_CHECKING, Union if TYPE_CHECKING: import tkinter -if __debug__: - from traceback import print_exc - from config import config from companion import ship_file_name from EDMCLogging import get_main_logger @@ -129,16 +126,18 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below if journal_dir is None: journal_dir = '' - + # TODO(A_D): this is ignored for type checking due to all the different types config.get returns # When that is refactored, remove the magic comment logdir = expanduser(journal_dir) # type: ignore # config is weird if not logdir or not isdir(logdir): + logger.error(f'Journal Directory is invalid: "{logdir}"') self.stop() return False if self.currentdir and self.currentdir != logdir: + logger.debug(f'Journal Directory changed? Was "{self.currentdir}", now "{logdir}"') self.stop() self.currentdir = logdir @@ -154,6 +153,7 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below self.logfile = join(self.currentdir, logfiles[-1]) if logfiles else None # type: ignore # config is weird except Exception: + logger.exception('Failed to find latest logfile') self.logfile = None return False @@ -174,10 +174,11 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below if not self.observed and not polling: self.observed = self.observer.schedule(self, self.currentdir) - logger.info(f'{"Polling" if polling else "Monitoring"} Journal Folder: {self.currentdir}') - logger.info(f'Start Journal File: {self.logfile}') + logger.info(f'{"Polling" if polling else "Monitoring"} Journal Folder: "{self.currentdir}"') + logger.info(f'Start Journal File: "{self.logfile}"') if not self.running(): + logger.debug('Starting Journal worker') self.thread = threading.Thread(target=self.worker, name='Journal worker') self.thread.daemon = True self.thread.start() @@ -231,6 +232,7 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below # event_generate() is the only safe way to poke the main thread from this thread: # https://mail.python.org/pipermail/tkinter-discuss/2013-November/003522.html + logger.debug(f'Starting on logfile "{self.logfile}"') # Seek to the end of the latest log file logfile = self.logfile if logfile: @@ -240,11 +242,13 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below for line in loghandle: try: + if b'"event":"Location"' in line: + logger.debug('"Location" event in the past at startup') + self.parse_entry(line) # Some events are of interest even in the past - except Exception: - if __debug__: - print('Invalid journal entry {!r}'.format(line)) + except Exception as ex: + logger.debug(f'Invalid journal entry:\n{line}\n', exc_info=ex) log_pos = loghandle.tell() @@ -302,12 +306,11 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below newlogfile = join(self.currentdir, logfiles[-1]) if logfiles else None # type: ignore except Exception: - if __debug__: - print_exc() - + logger.exception('Failed to find latest logfile') newlogfile = None if logfile != newlogfile: + logger.info(f'New Journal File. Was "{logfile}", now "{newlogfile}"') logfile = newlogfile if loghandle: loghandle.close() @@ -319,13 +322,13 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below log_pos = 0 - if __debug__: - print('New logfile {!r}'.format(logfile)) - if logfile: loghandle.seek(0, SEEK_END) # required to make macOS notice log change over SMB loghandle.seek(log_pos, SEEK_SET) # reset EOF flag # TODO: log_pos reported as possibly unbound for line in loghandle: + if b'"event":"Location"' in line: + logger.debug('Found "Location" event, appending to event_queue') + self.event_queue.append(line) if self.event_queue: @@ -337,10 +340,12 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below # Check whether we're still supposed to be running if threading.current_thread() != self.thread: + logger.inof("We're not meant to be running, exiting...") return # Terminate if self.game_was_running: if not self.game_running(): + logger.info('Detected exit from game, synthesising ShutDown event') self.event_queue.append( '{{ "timestamp":"{}", "event":"ShutDown" }}'.format(strftime('%Y-%m-%dT%H:%M:%SZ', gmtime())) ) @@ -478,11 +483,11 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below # Players *can* also purposefully set " " as the name, but anyone # doing that gets to live with EDMC showing ShipType instead. if entry['ShipName'] and entry['ShipName'] not in ('', ' '): - self.state['ShipName'] = entry['ShipName'] + self.state['ShipName'] = entry['ShipName'] self.state['ShipType'] = self.canonicalise(entry['Ship']) self.state['HullValue'] = entry.get('HullValue') # not present on exiting Outfitting - self.state['ModulesValue'] = entry.get('ModulesValue') # " + self.state['ModulesValue'] = entry.get('ModulesValue') # not present on exiting Outfitting self.state['Rebuy'] = entry.get('Rebuy') # Remove spurious differences between initial Loadout event and subsequent self.state['Modules'] = {} @@ -532,6 +537,9 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below if event_type in ('Location', 'CarrierJump'): self.planet = entry.get('Body') if entry.get('BodyType') == 'Planet' else None + if event_type == 'Location': + logger.debug('"Location" event') + elif event_type == 'FSDJump': self.planet = None @@ -777,11 +785,8 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below self.state['Friends'].discard(entry['Name']) return entry - except Exception: - if __debug__: - print('Invalid journal entry {!r}'.format(line)) - print_exc() - + except Exception as ex: + logger.debug(f'Invalid journal entry:\n{line}\n', exc_info=ex) return {'event': None} # Commodities, Modules and Ships can appear in different forms e.g. "$HNShockMount_Name;", "HNShockMount", @@ -808,12 +813,22 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below return item.capitalize() - def get_entry(self): + def get_entry(self) -> Union[OrderedDictT[str, Any], None]: + """ + Pull the next Journal event from the event_queue. + + :return: dict representing the event + """ if not self.event_queue: + logger.debug('Called with no event_queue') return None else: entry = self.parse_entry(self.event_queue.pop(0)) + + if entry['event'] == 'Location': + logger.debug('"Location" event') + if not self.live and entry['event'] not in (None, 'Fileheader'): # Game not running locally, but Journal has been updated self.live = True @@ -840,6 +855,9 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below ('SystemAddress', self.systemaddress), ]) + if entry['event'] == 'Location': + logger.debug('Appending "Location" event to event_queue') + self.event_queue.append(json.dumps(entry, separators=(', ', ':'))) elif self.live and entry['event'] == 'Music' and entry.get('MusicTrack') == 'MainMenu': diff --git a/plug.py b/plug.py index f3df95eb..4cc2cfa3 100644 --- a/plug.py +++ b/plug.py @@ -303,6 +303,9 @@ def notify_journal_entry(cmdr, is_beta, system, station, entry, state): :param is_beta: whether the player is in a Beta universe. :returns: Error message from the first plugin that returns one (if any) """ + if entry['event'] in ('Location'): + logger.debug('Notifying plugins of "Location" event') + error = None for plugin in PLUGINS: journal_entry = plugin._get_func('journal_entry') diff --git a/plugins/edsm.py b/plugins/edsm.py index b57575a3..3ce73a2c 100644 --- a/plugins/edsm.py +++ b/plugins/edsm.py @@ -530,7 +530,13 @@ def worker() -> None: if should_send(pending): if any(p for p in pending if p['event'] in ('CarrierJump', 'FSDJump', 'Location', 'Docked')): - logger.debug('CarrierJump (or FSDJump) in pending and it passed should_send()') + logger.debug("pending has at least one of " + "('CarrierJump', 'FSDJump', 'Location', 'Docked')" + " and it passed should_send()") + for p in pending: + if p['event'] in ('Location'): + logger.debug('"Location" event in pending passed should_send(), ' + f'timestamp: {p["timestamp"]}') creds = credentials(cmdr) # TODO: possibly unbound if creds is None: @@ -548,7 +554,14 @@ def worker() -> None: if any(p for p in pending if p['event'] in ('CarrierJump', 'FSDJump', 'Location', 'Docked')): data_elided = data.copy() data_elided['apiKey'] = '' - logger.debug(f'CarrierJump (or FSDJump): Attempting API call\ndata: {data_elided!r}') + logger.debug("pending has at least one of " + "('CarrierJump', 'FSDJump', 'Location', 'Docked')" + " Attempting API cal...") + + for p in pending: + if p['event'] in ('Location'): + logger.debug('Attempting API call for "Location" event with timestamp: ' + f'{p["timestamp"]}') r = this.session.post('https://www.edsm.net/api-journal-v1', data=data, timeout=_TIMEOUT) r.raise_for_status()