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