ED/EDMarketConnector
1
0
Fork 0
mirror of https://github.com/EDCD/EDMarketConnector.git synced 2025-04-22 20:00:29 +03:00
Code Issues Projects Releases Wiki Activity

Merge pull request #1243 from EDCD/enhancement/trace-logging-should-use-trace_if

Browse Source 
Convert all/most `logger.trace(...)` to `logger.trace_if(...)`
This commit is contained in:
Athanasius 2021-08-13 16:30:47 +01:00 committed by GitHub
commit bcadc079cc
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
11 changed files with 120 additions and 81 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

9
Contributing.md
View File

@ -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.

55
EDMC.py
View File

@ -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:

2
EDMCLogging.py
View File

@ -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

8
EDMarketConnector.py
View File

@ -174,7 +174,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':
@ -1108,7 +1108,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
@ -1199,7 +1199,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:
@ -1828,7 +1828,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)

5
companion.py
View File

@ -554,7 +554,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)
@ -564,7 +564,7 @@ class Session(object):
raise CredentialsError('cannot make a query when unauthorized')
try:
logger.trace('Trying...')
logger.trace_if('capi.query', 'Trying...')
r = self.session.get(self.server + endpoint, timeout=timeout) # type: ignore
except requests.ConnectionError as e:
@ -620,7 +620,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

20
journal_lock.py
View File

@ -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

36
monitor.py
View File

@ -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 <<JournalEvent>>')
logger.trace_if('journal.queue', 'Sending <<JournalEvent>>')
self.root.event_generate('<<JournalEvent>>', 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 <<JournalEvent>>')
logger.trace_if('journal.queue', 'Sending <<JournalEvent>>')
self.root.event_generate('<<JournalEvent>>', 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=(', ', ':')))

4
plug.py
View File

@ -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:

3
plugins/eddn.py
View File

@ -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: [<ValidationError: '[] is too short'>]"
):
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(

51
plugins/edsm.py
View File

@ -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'] = '<elided>'
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:

8
protocol.py
View File

@ -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("<<CompanionAuthEvent>>")')
self.master.event_generate('<<CompanionAuthEvent>>', 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()')