diff --git a/Contributing.md b/Contributing.md index 814ff7ca..c74953a1 100644 --- a/Contributing.md +++ b/Contributing.md @@ -416,13 +416,18 @@ In addition to that we utilise one of the user-defined levels as: method provided on `logger`: ```python - logger.trace_if('my-trace-rule', 'my-log-message') + logger.trace_if('journal.event.scan', 'my-log-message') ``` + The string used to identify this tracing should be related to the + **function of the code**, not the particular file, or class, that it is in. + This is so that the same string can be used to trace code that spans more + than one file, class, or other scope. + This would then be triggered by running EDMarketConnector with the appropriate command-line arguments: - EDMarketConnector.py --trace-on my-trace-rule + EDMarketConnector.py --trace-on journal.event.scan Note that you do **not** also need to specify `--trace`, that's implied. diff --git a/EDMC.py b/EDMC.py index b3e6d0c9..26dc6d7b 100755 --- a/EDMC.py +++ b/EDMC.py @@ -123,10 +123,25 @@ def main(): # noqa: C901, CCR001 help='Set the logging loglevel to one of: ' 'CRITICAL, ERROR, WARNING, INFO, DEBUG, TRACE', ) - group_loglevel.add_argument('--trace', - help='Set the Debug logging loglevel to TRACE', - action='store_true', - ) + + parser.add_argument( + '--trace', + help='Set the Debug logging loglevel to TRACE', + action='store_true', + ) + + parser.add_argument( + '--trace-on', + help='Mark the selected trace logging as active. "*" or "all" is equivalent to --trace-all', + action='append', + ) + + parser.add_argument( + "--trace-all", + help='Force trace level logging, with all possible --trace-on values active.', + action='store_true' + ) + parser.add_argument('-a', metavar='FILE', help='write ship loadout to FILE in Companion API json format') parser.add_argument('-e', metavar='FILE', help='write ship loadout to FILE in E:D Shipyard plain text format') parser.add_argument('-l', metavar='FILE', help='write ship locations to FILE in CSV format') @@ -150,8 +165,18 @@ def main(): # noqa: C901, CCR001 return - if args.trace: - edmclogger.set_channels_loglevel(logging.TRACE) + level_to_set: Optional[int] = None + if args.trace or args.trace_on: + level_to_set = logging.TRACE # type: ignore # it exists + logger.info('Setting TRACE level debugging due to either --trace or a --trace-on') + + if args.trace_all or (args.trace_on and ('*' in args.trace_on or 'all' in args.trace_on)): + level_to_set = logging.TRACE_ALL # type: ignore # it exists + logger.info('Setting TRACE_ALL level debugging due to either --trace-all or a --trace-on *|all') + + if level_to_set is not None: + logger.setLevel(level_to_set) + edmclogger.set_channels_loglevel(level_to_set) elif args.loglevel: if args.loglevel not in ('CRITICAL', 'ERROR', 'WARNING', 'INFO', 'DEBUG', 'TRACE'): @@ -166,6 +191,12 @@ exec_prefix: {sys.exec_prefix} executable: {sys.executable} sys.path: {sys.path}''' ) + if args.trace_on and len(args.trace_on) > 0: + import config as conf_module + + conf_module.trace_on = [x.casefold() for x in args.trace_on] # duplicate the list just in case + for d in conf_module.trace_on: + logger.info(f'marked {d} for TRACE') log_locale('Initial Locale') @@ -188,15 +219,15 @@ sys.path: {sys.path}''' # Get state from latest Journal file logger.debug('Getting state from latest journal file') try: - logdir = config.get_str('journaldir', default=config.default_journal_dir) - if not logdir: - logdir = config.default_journal_dir + monitor.currentdir = config.get_str('journaldir', default=config.default_journal_dir) + if not monitor.currentdir: + monitor.currentdir = config.default_journal_dir - logger.debug(f'logdir = "{logdir}"') - logfiles = sorted((x for x in os.listdir(logdir) if JOURNAL_RE.search(x)), + logger.debug(f'logdir = "{monitor.currentdir}"') + logfiles = sorted((x for x in os.listdir(monitor.currentdir) if JOURNAL_RE.search(x)), key=lambda x: x.split('.')[1:]) - logfile = join(logdir, logfiles[-1]) + logfile = join(monitor.currentdir, logfiles[-1]) logger.debug(f'Using logfile "{logfile}"') with open(logfile, 'r', encoding='utf-8') as loghandle: diff --git a/EDMCLogging.py b/EDMCLogging.py index 19dc60f6..c00b7ab9 100644 --- a/EDMCLogging.py +++ b/EDMCLogging.py @@ -42,12 +42,12 @@ import os import pathlib import tempfile from contextlib import suppress +from fnmatch import fnmatch # So that any warning about accessing a protected member is only in one place. from sys import _getframe as getframe from threading import get_native_id as thread_native_id from traceback import print_exc from typing import TYPE_CHECKING, Tuple, cast -from fnmatch import fnmatch import config as config_mod from config import appcmdname, appname, config diff --git a/EDMarketConnector.py b/EDMarketConnector.py index 886bf1a7..8385af2b 100755 --- a/EDMarketConnector.py +++ b/EDMarketConnector.py @@ -184,7 +184,7 @@ if __name__ == '__main__': # noqa: C901 def handle_edmc_callback_or_foregrounding() -> None: # noqa: CCR001 """Handle any edmc:// auth callback, else foreground existing window.""" - logger.trace('Begin...') + logger.trace_if('frontier-auth.windows', 'Begin...') if platform == 'win32': @@ -1118,7 +1118,7 @@ class AppWindow(object): entry = monitor.get_entry() if not entry: # This is expected due to some monitor.py code that appends `None` - # logger.trace('No entry from monitor.get_entry()') + logger.trace_if('journal.queue', 'No entry from monitor.get_entry()') return # Update main window @@ -1209,7 +1209,7 @@ class AppWindow(object): return # in CQC if not entry['event'] or not monitor.mode: - # logger.trace('Startup, returning') + logger.trace_if('journal.queue', 'Startup, returning') return # Startup if entry['event'] in ['StartUp', 'LoadGame'] and monitor.started: @@ -1838,7 +1838,7 @@ sys.path: {sys.path}''' ui_scale = 100 config.set('ui_scale', ui_scale) theme.default_ui_scale = root.tk.call('tk', 'scaling') - logger.trace(f'Default tk scaling = {theme.default_ui_scale}') + logger.trace_if('tk', f'Default tk scaling = {theme.default_ui_scale}') theme.startup_ui_scale = ui_scale root.tk.call('tk', 'scaling', theme.default_ui_scale * float(ui_scale) / 100.0) app = AppWindow(root) diff --git a/companion.py b/companion.py index 7f55fc7f..5b5842e1 100644 --- a/companion.py +++ b/companion.py @@ -561,7 +561,7 @@ class Session(object): def query(self, endpoint: str) -> CAPIData: # noqa: CCR001 """Perform a query against the specified CAPI endpoint.""" - logger.trace(f'Performing query for endpoint "{endpoint}"') + logger.trace_if('capi.query', f'Performing query for endpoint "{endpoint}"') if self.state == Session.STATE_INIT: if self.login(): return self.query(endpoint) @@ -571,7 +571,7 @@ class Session(object): raise CredentialsError('cannot make a query when unauthorized') try: - logger.trace('Trying...') + logger.trace_if('capi.query', 'Trying...') if conf_module.capi_pretend_down: raise ServerError('Pretending CAPI is down') @@ -630,7 +630,6 @@ class Session(object): self.retrying = False if 'timestamp' not in data: - # logger.trace('timestamp not in data, adding from response headers') data['timestamp'] = time.strftime('%Y-%m-%dT%H:%M:%SZ', parsedate(r.headers['Date'])) # type: ignore # Update Odyssey Suit data diff --git a/journal_lock.py b/journal_lock.py index d038709d..6b2e9951 100644 --- a/journal_lock.py +++ b/journal_lock.py @@ -56,7 +56,7 @@ class JournalLock: def open_journal_dir_lockfile(self) -> bool: """Open journal_dir lockfile ready for locking.""" self.journal_dir_lockfile_name = self.journal_dir_path / 'edmc-journal-lock.txt' # type: ignore - logger.trace(f'journal_dir_lockfile_name = {self.journal_dir_lockfile_name!r}') + logger.trace_if('journal-lock', f'journal_dir_lockfile_name = {self.journal_dir_lockfile_name!r}') try: self.journal_dir_lockfile = open(self.journal_dir_lockfile_name, mode='w+', encoding='utf-8') @@ -95,7 +95,7 @@ class JournalLock: :return: LockResult - See the class Enum definition """ if platform == 'win32': - logger.trace('win32, using msvcrt') + logger.trace_if('journal-lock', 'win32, using msvcrt') # win32 doesn't have fcntl, so we have to use msvcrt import msvcrt @@ -108,7 +108,7 @@ class JournalLock: return JournalLockResult.ALREADY_LOCKED else: # pytest coverage only sees this on !win32 - logger.trace('NOT win32, using fcntl') + logger.trace_if('journal-lock', 'NOT win32, using fcntl') try: import fcntl @@ -128,7 +128,7 @@ class JournalLock: self.journal_dir_lockfile.write(f"Path: {self.journal_dir}\nPID: {os_getpid()}\n") self.journal_dir_lockfile.flush() - logger.trace('Done') + logger.trace_if('journal-lock', 'Done') self.locked = True return JournalLockResult.LOCKED @@ -144,7 +144,7 @@ class JournalLock: unlocked = False if platform == 'win32': - logger.trace('win32, using msvcrt') + logger.trace_if('journal-lock', 'win32, using msvcrt') # win32 doesn't have fcntl, so we have to use msvcrt import msvcrt @@ -161,7 +161,7 @@ class JournalLock: unlocked = True else: # pytest coverage only sees this on !win32 - logger.trace('NOT win32, using fcntl') + logger.trace_if('journal-lock', 'NOT win32, using fcntl') try: import fcntl @@ -235,19 +235,19 @@ class JournalLock: def retry(self) -> None: """Handle user electing to Retry obtaining the lock.""" - logger.trace('User selected: Retry') + logger.trace_if('journal-lock_if', 'User selected: Retry') self.destroy() self.callback(True, self.parent) def ignore(self) -> None: """Handle user electing to Ignore failure to obtain the lock.""" - logger.trace('User selected: Ignore') + logger.trace_if('journal-lock', 'User selected: Ignore') self.destroy() self.callback(False, self.parent) def _destroy(self) -> None: """Destroy the Retry/Ignore popup.""" - logger.trace('User force-closed popup, treating as Ignore') + logger.trace_if('journal-lock', 'User force-closed popup, treating as Ignore') self.ignore() def update_lock(self, parent: tk.Tk) -> None: @@ -277,7 +277,7 @@ class JournalLock: :param retry: - does the user want to retry? Comes from the dialogue choice. :param parent: - The parent tkinter window. """ - logger.trace(f'We should retry: {retry}') + logger.trace_if('journal-lock', f'We should retry: {retry}') if not retry: return diff --git a/monitor.py b/monitor.py index dac75ae9..debba020 100644 --- a/monitor.py +++ b/monitor.py @@ -24,7 +24,7 @@ from edmc_data import edmc_suit_shortnames, edmc_suit_symbol_localised from EDMCLogging import get_main_logger logger = get_main_logger() -STARTUP = 'startup' +STARTUP = 'journal.startup' if TYPE_CHECKING: def _(x: str) -> str: @@ -336,8 +336,8 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below for line in loghandle: try: - # if b'"event":"Location"' in line: - # logger.trace('"Location" event in the past at startup') + if b'"event":"Location"' in line: + logger.trace_if('journal.locations', '"Location" event in the past at startup') self.parse_entry(line) # Some events are of interest even in the past @@ -417,22 +417,22 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below if b'"event":"Continue"' in line: for _ in range(10): - logger.trace("****") - logger.trace('Found a Continue event, its being added to the list, we will finish this file up' - ' and then continue with the next') + logger.trace_if('journal.continuation', "****") + logger.trace_if('journal.continuation', 'Found a Continue event, its being added to the list, ' + 'we will finish this file up and then continue with the next') self.event_queue.put(line) if not self.event_queue.empty(): if not config.shutting_down: - # logger.trace('Sending <>') + logger.trace_if('journal.queue', 'Sending <>') self.root.event_generate('<>', when="tail") log_pos = loghandle.tell() if logfile != newlogfile: for _ in range(10): - logger.trace("****") + logger.trace_if('journal.file', "****") logger.info(f'New Journal File. Was "{logfile}", now "{newlogfile}"') logfile = newlogfile if loghandle: @@ -464,7 +464,7 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below ) if not config.shutting_down: - # logger.trace('Sending <>') + logger.trace_if('journal.queue', 'Sending <>') self.root.event_generate('<>', when="tail") self.game_was_running = False @@ -530,7 +530,7 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below self.cmdr = entry['Commander'] # 'Open', 'Solo', 'Group', or None for CQC (and Training - but no LoadGame event) if not entry.get('Ship') and not entry.get('GameMode') or entry.get('GameMode', '').lower() == 'cqc': - logger.trace_if('cqc-loadgame-events', f'loadgame to cqc: {entry}') + logger.trace_if('journal.loadgame.cqc', f'loadgame to cqc: {entry}') self.mode = 'CQC' else: @@ -764,8 +764,8 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below self.state['Body'] = entry.get('Body') self.state['BodyType'] = entry.get('BodyType') - # if event_type == 'location': - # logger.trace('"Location" event') + if event_type == 'location': + logger.trace_if('journal.locations', '"Location" event') elif event_type == 'fsdjump': self.planet = None @@ -1869,16 +1869,16 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below logger.debug('Called whilst self.thread is None, returning') return None - # logger.trace('Begin') + logger.trace_if('journal.queue', 'Begin') if self.event_queue.empty() and self.game_running(): logger.error('event_queue is empty whilst game_running, this should not happen, returning') return None - # logger.trace('event_queue NOT empty') + logger.trace_if('journal.queue', 'event_queue NOT empty') entry = self.parse_entry(self.event_queue.get_nowait()) - # if entry['event'] == 'Location': - # logger.trace('"Location" event') + if entry['event'] == 'Location': + logger.trace_if('journal.locations', '"Location" event') if not self.live and entry['event'] not in (None, 'Fileheader'): # Game not running locally, but Journal has been updated @@ -1906,8 +1906,8 @@ class EDLogs(FileSystemEventHandler): # type: ignore # See below ('SystemAddress', self.systemaddress), ]) - # if entry['event'] == 'Location': - # logger.trace('Appending "Location" event to event_queue') + if entry['event'] == 'Location': + logger.trace_if('journal.locations', 'Appending "Location" event to event_queue') self.event_queue.put(json.dumps(entry, separators=(', ', ':'))) diff --git a/plug.py b/plug.py index 2899c237..2f3ab888 100644 --- a/plug.py +++ b/plug.py @@ -257,8 +257,8 @@ 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.trace('Notifying plugins of "Location" event') + if entry['event'] in ('Location'): + logger.trace_if('journal.locations', 'Notifying plugins of "Location" event') error = None for plugin in PLUGINS: diff --git a/plugins/eddn.py b/plugins/eddn.py index 194a52de..e532c8a8 100644 --- a/plugins/eddn.py +++ b/plugins/eddn.py @@ -87,6 +87,7 @@ HORIZ_SKU = 'ELITE_HORIZONS_V_PLANETARY_LANDINGS' class EDDN: """EDDN Data export.""" + DEBUG = 'eddn' in debug_senders SERVER = 'https://eddn.edcd.io:4430' if DEBUG: @@ -193,7 +194,7 @@ class EDDN: and msg['message']['commodities'] == [] and r.text == "FAIL: []" ): - logger.trace("EDDN is still objecting to empty commodities data") + logger.trace_if('plugin.eddn', "EDDN is still objecting to empty commodities data") return # We want to silence warnings otherwise logger.debug( diff --git a/plugins/edsm.py b/plugins/edsm.py index 76ac203e..5f23ba23 100644 --- a/plugins/edsm.py +++ b/plugins/edsm.py @@ -39,8 +39,7 @@ _TIMEOUT = 20 DISCARDED_EVENTS_SLEEP = 10 # trace-if events -CMDR_EVENTS = 'edsm-cmdr-events' -LOCATION_EVENTS = 'edsm-locations' +CMDR_EVENTS = 'plugin.edsm.cmdr-events' class This: @@ -407,14 +406,15 @@ def journal_entry( # noqa: C901, CCR001 return this.on_foot = state['OnFoot'] - # if entry['event'] in ('CarrierJump', 'FSDJump', 'Location', 'Docked'): - # logger.trace(f'''{entry["event"]} -# Commander: {cmdr} -# System: {system} -# Station: {station} -# state: {state!r} -# entry: {entry!r}''' -# ) + if entry['event'] in ('CarrierJump', 'FSDJump', 'Location', 'Docked'): + logger.trace_if( + 'journal.locations', f'''{entry["event"]} +Commander: {cmdr} +System: {system} +Station: {station} +state: {state!r} +entry: {entry!r}''' + ) # Always update our system address even if we're not currently the provider for system or station, but dont update # on events that contain "future" data, such as FSDTarget if entry['event'] in ('Location', 'Docked', 'CarrierJump', 'FSDJump'): @@ -519,10 +519,11 @@ def journal_entry( # noqa: C901, CCR001 this.queue.put((cmdr, materials)) - # if entry['event'] in ('CarrierJump', 'FSDJump', 'Location', 'Docked'): - # logger.trace(f'''{entry["event"]} -# Queueing: {entry!r}''' -# ) + if entry['event'] in ('CarrierJump', 'FSDJump', 'Location', 'Docked'): + logger.trace_if( + 'journal.locations', f'''{entry["event"]} +Queueing: {entry!r}''' + ) logger.trace_if(CMDR_EVENTS, f'"{entry["event"]=}" event, queueing: {cmdr=}') this.queue.put((cmdr, entry)) @@ -656,13 +657,15 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently logger.trace_if(CMDR_EVENTS, f'pending contains:\n{chr(0x0A).join(str(p) for p in pending)}') if any(p for p in pending if p['event'] in ('CarrierJump', 'FSDJump', 'Location', 'Docked')): - logger.trace_if(LOCATION_EVENTS, "pending has at least one of " + logger.trace_if('journal.locations', "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.trace_if(LOCATION_EVENTS, '"Location" event in pending passed should_send(), ' - f'timestamp: {p["timestamp"]}') + logger.trace_if( + 'journal.locations', + f'"Location" event in pending passed should_send(),timestamp: {p["timestamp"]}' + ) creds = credentials(cmdr) # TODO: possibly unbound if creds is None: @@ -683,25 +686,25 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently data_elided = data.copy() data_elided['apiKey'] = '' logger.trace_if( - LOCATION_EVENTS, + 'journal.locations', "pending has at least one of ('CarrierJump', 'FSDJump', 'Location', 'Docked')" " Attempting API call with the following events:" ) for p in pending: - logger.trace_if(LOCATION_EVENTS, f"Event: {p!r}") + logger.trace_if('journal.locations', f"Event: {p!r}") if p['event'] in ('Location'): logger.trace_if( - LOCATION_EVENTS, + 'journal.locations', f'Attempting API call for "Location" event with timestamp: {p["timestamp"]}' ) logger.trace_if( - LOCATION_EVENTS, f'Overall POST data (elided) is:\n{json.dumps(data_elided, indent=2)}' + 'journal.locations', f'Overall POST data (elided) is:\n{json.dumps(data_elided, indent=2)}' ) r = this.session.post(TARGET_URL, data=data, timeout=_TIMEOUT) - # logger.trace(f'API response content: {r.content}') + logger.trace_if('plugin.edsm.api', f'API response content: {r.content!r}') r.raise_for_status() reply = r.json() @@ -720,11 +723,11 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently else: if msg_num // 100 == 1: - # logger.trace('Overall OK') + logger.trace_if('plugin.edsm.api', 'Overall OK') pass elif msg_num // 100 == 5: - # logger.trace('Event(s) not currently processed, but saved for later') + logger.trace_if('plugin.edsm.api', 'Event(s) not currently processed, but saved for later') pass else: diff --git a/protocol.py b/protocol.py index 2a0e229e..ce5ea042 100644 --- a/protocol.py +++ b/protocol.py @@ -48,7 +48,7 @@ class GenericProtocolHandler: """Generate an auth event.""" self.lastpayload = url - logger.trace(f'Payload: {self.lastpayload}') + logger.trace_if('frontier-auth', f'Payload: {self.lastpayload}') if not config.shutting_down: logger.debug('event_generate("<>")') self.master.event_generate('<>', when="tail") @@ -298,7 +298,7 @@ elif (config.auth_force_edmc_protocol msg = MSG() # Calls GetMessageW: https://docs.microsoft.com/en-us/windows/win32/api/winuser/nf-winuser-getmessagew while GetMessageW(byref(msg), None, 0, 0) != 0: - logger.trace(f'DDE message of type: {msg.message}') + logger.trace_if('frontier-auth.windows', f'DDE message of type: {msg.message}') if msg.message == WM_DDE_EXECUTE: # GlobalLock does some sort of "please dont move this?" # https://docs.microsoft.com/en-us/windows/win32/api/winbase/nf-winbase-globallock @@ -306,7 +306,7 @@ elif (config.auth_force_edmc_protocol GlobalUnlock(msg.lParam) # Unlocks the GlobalLock-ed object if args.lower().startswith('open("') and args.endswith('")'): - logger.trace(f'args are: {args}') + logger.trace_if('frontier-auth.windows', f'args are: {args}') url = urllib.parse.unquote(args[6:-2]).strip() if url.startswith(self.redirect): logger.debug(f'Message starts with {self.redirect}') @@ -384,7 +384,7 @@ else: # Linux / Run from source def parse(self) -> bool: """Parse a request.""" - logger.trace(f'Got message on path: {self.path}') + logger.trace_if('frontier-auth.http', f'Got message on path: {self.path}') url = urllib.parse.unquote(self.path) if url.startswith('/auth'): logger.debug('Request starts with /auth, sending to protocolhandler.event()') diff --git a/requirements-dev.txt b/requirements-dev.txt index 066f636d..734264f1 100644 --- a/requirements-dev.txt +++ b/requirements-dev.txt @@ -6,7 +6,7 @@ wheel flake8==3.9.2 flake8-annotations-coverage==0.0.5 flake8-cognitive-complexity==0.1.0 -flake8-comprehensions==3.5.0 +flake8-comprehensions==3.6.0 flake8-docstrings==1.6.0 isort==5.9.3 flake8-isort==4.0.0