Place detailed logging for "Location" events.

To try and track down what's happening with #713

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)

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:

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'{"Polling" if polling else "Monitoring"} Journal Folder: "{self.currentdir}"')
-        logger.info(f'Start Journal File: {self.logfile}')
+        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:
+                except Exception as ex:
-                    if __debug__:
+                    logger.debug(f'Invalid journal entry:\n{line}\n', exc_info=ex)
-                        print('Invalid journal entry {!r}'.format(line))
 
             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__:
+                    logger.exception('Failed to find latest logfile')
-                        print_exc()
-
                     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:
+        except Exception as ex:
-            if __debug__:
+            logger.debug(f'Invalid journal entry:\n{line}\n', exc_info=ex)
-                print('Invalid journal entry {!r}'.format(line))
-                print_exc()
-
             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':

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

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'] = '<elided>'
-                        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()