From 40b76d40cc8125f8025ab7db439d4d115b81ebe4 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 5 Aug 2021 13:43:15 +0100 Subject: [PATCH 01/13] Add `--trace-on ...` to activate specific trace logging This is just the parsing and storage of the options for now. --- EDMarketConnector.py | 13 +++++++++++++ config.py | 3 +++ 2 files changed, 16 insertions(+) diff --git a/EDMarketConnector.py b/EDMarketConnector.py index 17cfdd01c..b8887c6e5 100755 --- a/EDMarketConnector.py +++ b/EDMarketConnector.py @@ -99,6 +99,12 @@ action='append', ) + parser.add_argument( + '--trace-on', + help='Mark the selected trace logging as active.', + action='append', + ) + auth_options = parser.add_mutually_exclusive_group(required=False) auth_options.add_argument('--force-localserver-for-auth', help='Force EDMC to use a localhost webserver for Frontier Auth callback', @@ -146,6 +152,13 @@ debug_webserver.run_listener(DEBUG_WEBSERVER_HOST, DEBUG_WEBSERVER_PORT) + 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') + def handle_edmc_callback_or_foregrounding() -> None: # noqa: CCR001 """Handle any edmc:// auth callback, else foreground existing window.""" logger.trace('Begin...') diff --git a/config.py b/config.py index 6e305edb7..6b9d3016c 100644 --- a/config.py +++ b/config.py @@ -41,6 +41,9 @@ update_interval = 8*60*60 # Providers marked to be in debug mode. Generally this is expected to switch to sending data to a log file debug_senders: List[str] = [] +# TRACE logging code that should actually be used. Means not spamming it +# *all* if only interested in some things. +trace_on: List[str] = [] # This must be done here in order to avoid an import cycle with EDMCLogging. # Other code should use EDMCLogging.get_main_logger From ea88a57e180cd3c08b256a409f2b0df500b8e988 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 5 Aug 2021 13:46:20 +0100 Subject: [PATCH 02/13] monitor: Gate Commander/LoadGame TRACE on trace_on 'startup' --- monitor.py | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/monitor.py b/monitor.py index 05a10c65e..f1390b142 100644 --- a/monitor.py +++ b/monitor.py @@ -19,7 +19,7 @@ import tkinter import util_ships -from config import config +from config import config, trace_on from edmc_data import edmc_suit_shortnames, edmc_suit_symbol_localised from EDMCLogging import get_main_logger @@ -518,6 +518,8 @@ def parse_entry(self, line: bytes) -> MutableMapping[str, Any]: # noqa: C901, C self.live = True # First event in 3.0 self.cmdr = entry['Name'] self.state['FID'] = entry['FID'] + if 'startup' in trace_on: + logger.trace(f'"Commander" event, {monitor.cmdr=}, {monitor.state["FID"]=}') elif event_type == 'loadgame': # Odyssey Release Update 5 -- This contains data that doesn't match the format used in FileHeader above @@ -559,6 +561,9 @@ def parse_entry(self, line: bytes) -> MutableMapping[str, Any]: # noqa: C901, C if entry.get('Ship') is not None and self._RE_SHIP_ONFOOT.search(entry['Ship']): self.state['OnFoot'] = True + if 'startup' in trace_on: + logger.trace(f'"LoadGame" event, {monitor.cmdr=}, {monitor.state["FID"]=}') + elif event_type == 'newcommander': self.cmdr = entry['Name'] self.group = None From 56d7ee64beaba4aedf8c54ca003c133260e4095a Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 5 Aug 2021 14:06:42 +0100 Subject: [PATCH 03/13] plugins/edsm: Add trace-on support & cleanup some mypy changes * trace-on 'edsm-cmdr-events' for how Commanders, their API keys and using them are handled. See #1134 * trace-on 'edsm-locations' for what was commented-out logging to do with ensuring code reacted correctly to any change of system. * mypy/types-* seem to have had changes causing extra carping, so addressing that. --- plugins/edsm.py | 112 ++++++++++++++++++++++++++++++++++-------------- 1 file changed, 81 insertions(+), 31 deletions(-) diff --git a/plugins/edsm.py b/plugins/edsm.py index 4681cc7b0..8c79c4484 100644 --- a/plugins/edsm.py +++ b/plugins/edsm.py @@ -14,7 +14,7 @@ import tkinter as tk from queue import Queue from threading import Thread -from typing import TYPE_CHECKING, Any, List, Mapping, MutableMapping, Optional, Tuple +from typing import TYPE_CHECKING, Any, List, Literal, Mapping, MutableMapping, Optional, Tuple, Union import requests @@ -22,7 +22,7 @@ import myNotebook as nb # noqa: N813 import plug from companion import CAPIData -from config import applongname, appversion, config, debug_senders +from config import applongname, appversion, config, debug_senders, trace_on from edmc_data import DEBUG_WEBSERVER_HOST, DEBUG_WEBSERVER_PORT from EDMCLogging import get_main_logger from ttkHyperlinkLabel import HyperlinkLabel @@ -128,7 +128,8 @@ def plugin_start3(plugin_dir: str) -> str: # Migrate old settings if not config.get_list('edsm_cmdrs'): - if isinstance(config.get_list('cmdrs'), list) and config.get_list('edsm_usernames') and config.get_list('edsm_apikeys'): + if isinstance(config.get_list('cmdrs'), list) and \ + config.get_list('edsm_usernames') and config.get_list('edsm_apikeys'): # Migrate <= 2.34 settings config.set('edsm_cmdrs', config.get_list('cmdrs')) @@ -262,7 +263,7 @@ def prefs_cmdr_changed(cmdr: str, is_beta: bool) -> None: # LANG: We have no data on the current commander this.cmdr_text['text'] = _('None') - to_set = tk.DISABLED + to_set: Union[Literal['normal'], Literal['disabled']] = tk.DISABLED if cmdr and not is_beta and this.log.get(): to_set = tk.NORMAL @@ -326,6 +327,9 @@ def credentials(cmdr: str) -> Optional[Tuple[str, str]]: :param cmdr: The commander to get credentials for :return: The credentials, or None """ + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'{cmdr=}') + # Credentials for cmdr if not cmdr: return None @@ -343,13 +347,19 @@ def credentials(cmdr: str) -> Optional[Tuple[str, str]]: if idx >= len(edsm_usernames) or idx >= len(edsm_apikeys): return None + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'{cmdr=}: returning ({edsm_usernames[idx]=}, {edsm_apikeys[idx]=})') + return (edsm_usernames[idx], edsm_apikeys[idx]) else: + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'{cmdr=}: returning None') + return None -def journal_entry( +def journal_entry( # noqa: C901, CCR001 cmdr: str, is_beta: bool, system: str, station: str, entry: MutableMapping[str, Any], state: Mapping[str, Any] ) -> None: """Journal Entry hook.""" @@ -475,12 +485,18 @@ def journal_entry( 'Encoded': [{'Name': k, 'Count': v} for k, v in state['Encoded'].items()], } materials.update(transient) + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'"LoadGame" event, queueing Materials: {cmdr=}') + this.queue.put((cmdr, materials)) # if entry['event'] in ('CarrierJump', 'FSDJump', 'Location', 'Docked'): # logger.trace(f'''{entry["event"]} # Queueing: {entry!r}''' # ) + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'"{entry["event"]=}" event, queueing: {cmdr=}') + this.queue.put((cmdr, entry)) @@ -543,8 +559,10 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently Processes `this.queue` until the queued item is None. """ logger.debug('Starting...') - pending = [] # Unsent events + pending: List[Mapping[str, Any]] = [] # Unsent events closing = False + cmdr: str = "" + entry: Mapping[str, Any] = {} while True: item: Optional[Tuple[str, Mapping[str, Any]]] = this.queue.get() @@ -555,6 +573,9 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently logger.debug('Empty queue message, setting closing = True') closing = True # Try to send any unsent events before we close + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'De-queued ({cmdr=}, {entry["event"]=})') + retrying = 0 while retrying < 3: if (res := killswitch.get_disabled("plugins.edsm.worker")).disabled: @@ -567,10 +588,13 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently # Tell the type checker that these two are bound. # TODO: While this works because of the item check below, these names are still technically unbound # TODO: in some cases, therefore this should be refactored. - cmdr: str = "" - entry: Mapping[str, Any] = {} + cmdr = "" + entry = {} if item and entry['event'] not in this.discardedEvents: # TODO: Technically entry can be unbound here. + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'({cmdr=}, {entry["event"]=}): not in discardedEvents, appending to pending') + pending.append(entry) # Get list of events to discard @@ -591,20 +615,29 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently pending = list(filter(lambda x: x['event'] not in this.discardedEvents, pending)) if should_send(pending): - # if any(p for p in pending if p['event'] in ('CarrierJump', 'FSDJump', 'Location', 'Docked')): - # logger.trace("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('"Location" event in pending passed should_send(), ' - # f'timestamp: {p["timestamp"]}') + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'({cmdr=}, {entry["event"]=}): should_send() said True') + pendings = [f"{p}\n" for p in pending] + logger.trace(f'pending contains:\n{pendings}') + + if 'edsm-locations' in trace_on and \ + any(p for p in pending if p['event'] in ('CarrierJump', 'FSDJump', 'Location', 'Docked')): + logger.trace("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('"Location" event in pending passed should_send(), ' + f'timestamp: {p["timestamp"]}') creds = credentials(cmdr) # TODO: possibly unbound if creds is None: raise ValueError("Unexpected lack of credentials") username, apikey = creds + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'({cmdr=}, {entry["event"]=}): Using {username=} from credentials()') + data = { 'commanderName': username.encode('utf-8'), 'apiKey': apikey, @@ -613,22 +646,23 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently 'message': json.dumps(pending, ensure_ascii=False).encode('utf-8'), } - # if any(p for p in pending if p['event'] in ('CarrierJump', 'FSDJump', 'Location', 'Docked')): - # data_elided = data.copy() - # data_elided['apiKey'] = '' - # logger.trace( - # "pending has at least one of " - # "('CarrierJump', 'FSDJump', 'Location', 'Docked')" - # " Attempting API call with the following events:" - # ) + if 'edsm-locations' in trace_on and \ + any(p for p in pending if p['event'] in ('CarrierJump', 'FSDJump', 'Location', 'Docked')): + data_elided = data.copy() + data_elided['apiKey'] = '' + logger.trace( + "pending has at least one of " + "('CarrierJump', 'FSDJump', 'Location', 'Docked')" + " Attempting API call with the following events:" + ) - # for p in pending: - # logger.trace(f"Event: {p!r}") - # if p['event'] in ('Location'): - # logger.trace('Attempting API call for "Location" event with timestamp: ' - # f'{p["timestamp"]}') + for p in pending: + logger.trace(f"Event: {p!r}") + if p['event'] in ('Location'): + logger.trace('Attempting API call for "Location" event with timestamp: ' + f'{p["timestamp"]}') - # logger.trace(f'Overall POST data (elided) is:\n{data_elided}') + logger.trace(f'Overall POST data (elided) is:\n{data_elided}') r = this.session.post(TARGET_URL, data=data, timeout=_TIMEOUT) # logger.trace(f'API response content: {r.content}') @@ -691,7 +725,7 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently logger.debug('Done.') -def should_send(entries: List[Mapping[str, Any]]) -> bool: +def should_send(entries: List[Mapping[str, Any]]) -> bool: # noqa: CCR001 """ Whether or not any of the given entries should be sent to EDSM. @@ -703,6 +737,9 @@ def should_send(entries: List[Mapping[str, Any]]) -> bool: if entries and entries[-1]['event'] == 'Scan': this.navbeaconscan -= 1 if this.navbeaconscan: + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'False because {this.navbeaconscan=}') + return False else: @@ -717,6 +754,9 @@ def should_send(entries: List[Mapping[str, Any]]) -> bool: # Cargo is the last event on startup, unless starting when docked in which case Docked is the last event this.newgame = False this.newgame_docked = False + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'True because {entry["event"]=}') + return True elif this.newgame: @@ -726,8 +766,18 @@ def should_send(entries: List[Mapping[str, Any]]) -> bool: 'CommunityGoal', # Spammed periodically 'ModuleBuy', 'ModuleSell', 'ModuleSwap', # will be shortly followed by "Loadout" 'ShipyardBuy', 'ShipyardNew', 'ShipyardSwap'): # " + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'True because {entry["event"]=}') + return True + else: + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'{entry["event"]=}, {this.newgame_docked=}') + + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'False as default: {entry["event"]=}, {this.newgame_docked=}') + return False From ba7c2de5934ef6ec5252d032fd68ff3275d4d530 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 5 Aug 2021 14:40:41 +0100 Subject: [PATCH 04/13] plugins/edsm: 'class This' the file & flake8/mypy cleanup --- plugins/edsm.py | 82 +++++++++++++++++++++++++++++++++---------------- 1 file changed, 55 insertions(+), 27 deletions(-) diff --git a/plugins/edsm.py b/plugins/edsm.py index 8c79c4484..2561dc3b6 100644 --- a/plugins/edsm.py +++ b/plugins/edsm.py @@ -10,11 +10,11 @@ # text is always fired. i.e. CAPI cmdr_data() processing. import json -import sys +import threading import tkinter as tk from queue import Queue from threading import Thread -from typing import TYPE_CHECKING, Any, List, Literal, Mapping, MutableMapping, Optional, Tuple, Union +from typing import TYPE_CHECKING, Any, List, Literal, Mapping, MutableMapping, Optional, Set, Tuple, Union import requests @@ -37,26 +37,54 @@ def _(x: str) -> str: _TIMEOUT = 20 -this: Any = sys.modules[__name__] # For holding module globals -this.session: requests.Session = requests.Session() -this.queue: Queue = Queue() # Items to be sent to EDSM by worker thread -this.discardedEvents: List[str] = [] # List discarded events from EDSM -this.lastlookup: bool = False # whether the last lookup succeeded - -# Game state -this.multicrew: bool = False # don't send captain's ship info to EDSM while on a crew -this.coordinates: Optional[Tuple[int, int, int]] = None -this.newgame: bool = False # starting up - batch initial burst of events -this.newgame_docked: bool = False # starting up while docked -this.navbeaconscan: int = 0 # batch up burst of Scan events after NavBeaconScan -this.system_link: tk.Tk = None -this.system: tk.Tk = None -this.system_address: Optional[int] = None # Frontier SystemAddress -this.system_population: Optional[int] = None -this.station_link: tk.Tk = None -this.station: Optional[str] = None -this.station_marketid: Optional[int] = None # Frontier MarketID -this.on_foot = False +class This: + """Holds module globals.""" + + def __init__(self): + self.session: requests.Session = requests.Session() + self.queue: Queue = Queue() # Items to be sent to EDSM by worker thread + self.discardedEvents: Set[str] = [] # List discarded events from EDSM + self.lastlookup: requests.Response # Result of last system lookup + + # Game state + self.multicrew: bool = False # don't send captain's ship info to EDSM while on a crew + self.coordinates: Optional[Tuple[int, int, int]] = None + self.newgame: bool = False # starting up - batch initial burst of events + self.newgame_docked: bool = False # starting up while docked + self.navbeaconscan: int = 0 # batch up burst of Scan events after NavBeaconScan + self.system_link: tk.Widget = None + self.system: tk.Tk = None + self.system_address: Optional[int] = None # Frontier SystemAddress + self.system_population: Optional[int] = None + self.station_link: tk.Widget = None + self.station: Optional[str] = None + self.station_marketid: Optional[int] = None # Frontier MarketID + self.on_foot = False + + self._IMG_KNOWN = None + self._IMG_UNKNOWN = None + self._IMG_NEW = None + self._IMG_ERROR = None + + self.thread: Optional[threading.Thread] = None + + self.log = None + self.log_button = None + + self.label = None + + self.cmdr_label = None + self.cmdr_text = None + + self.user_label = None + self.user = None + + self.apikey_label = None + self.apikey = None + + +this = This() + STATION_UNDOCKED: str = '×' # "Station" name to display when not docked = U+00D7 __cleanup = str.maketrans({' ': None, '\n': None}) IMG_KNOWN_B64 = """ @@ -169,7 +197,7 @@ def plugin_stop() -> None: logger.debug('Signalling queue to close...') # Signal thread to close and wait for it this.queue.put(None) - this.thread.join() + this.thread.join() # type: ignore this.thread = None this.session.close() # Suppress 'Exception ignored in: ' errors # TODO: this is bad. @@ -421,7 +449,7 @@ def journal_entry( # noqa: C901, CCR001 to_set = '' this.station_link['text'] = to_set - this.station_link['url'] = station_url(this.system, str(this.station)) + this.station_link['url'] = station_url(str(this.system), str(this.station)) this.station_link.update_idletasks() # Update display of 'EDSM Status' image @@ -702,9 +730,9 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently if not config.shutting_down: this.system_link.event_generate('<>', when="tail") - if r['msgnum'] // 100 != 1: - logger.warning(f'EDSM event with not-1xx status:\n{r["msgnum"]}\n{r["msg"]}\n' - f'{json.dumps(e, separators = (",", ": "))}') + if r['msgnum'] // 100 != 1: # type: ignore + logger.warning(f'EDSM event with not-1xx status:\n{r["msgnum"]}\n' # type: ignore + f'{r["msg"]}\n{json.dumps(e, separators = (",", ": "))}') pending = [] From 26115a14f0a613309d628ec76980c04ace3b8441 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 5 Aug 2021 15:01:33 +0100 Subject: [PATCH 05/13] plugins/edsm: should_send() == True for any Shutdown event We MUST attempt flushing pending events in case of commander change. --- plugins/edsm.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/plugins/edsm.py b/plugins/edsm.py index 2561dc3b6..b1b388ebd 100644 --- a/plugins/edsm.py +++ b/plugins/edsm.py @@ -760,6 +760,13 @@ def should_send(entries: List[Mapping[str, Any]]) -> bool: # noqa: CCR001 :param entries: The entries to check :return: bool indicating whether or not to send said entries """ + # We MUST flush pending on logout, in case new login is a different Commander + if any(e for e in entries if e['event'] == 'Shutdown'): + if 'edsm-cmdr-events' in trace_on: + logger.trace('True because Shutdown') + + return True + # batch up burst of Scan events after NavBeaconScan if this.navbeaconscan: if entries and entries[-1]['event'] == 'Scan': From 53da204ffd80801305f5a0ca36c91798dbeac733 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 5 Aug 2021 15:19:43 +0100 Subject: [PATCH 06/13] plugins/edsm: Empty pending on Shutdown & --- plugins/edsm.py | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/plugins/edsm.py b/plugins/edsm.py index b1b388ebd..dfc651e57 100644 --- a/plugins/edsm.py +++ b/plugins/edsm.py @@ -746,6 +746,12 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently # LANG: EDSM Plugin - Error connecting to EDSM API plug.show_error(_("Error: Can't connect to EDSM")) + if entry['event'].lower() == 'shutdown': + # Game shutdown so we MUST not hang on to pending + pending = [] + if 'edsm-cmdr-events' in trace_on: + logger.trace('Blanked pending because of shutdown event') + if closing: logger.debug('closing, so returning.') return From ddc9286903d8c1e032d20dd14d26eab8e5e0c6af Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 5 Aug 2021 15:20:03 +0100 Subject: [PATCH 07/13] plugins/edsm: Queue *all* events to worker We need to trigger off ShutDown and Commander/LoadGame to empty pending, so need to *see* them in the worker. --- plugins/edsm.py | 7 ++----- 1 file changed, 2 insertions(+), 5 deletions(-) diff --git a/plugins/edsm.py b/plugins/edsm.py index dfc651e57..b949670f6 100644 --- a/plugins/edsm.py +++ b/plugins/edsm.py @@ -488,11 +488,8 @@ def journal_entry( # noqa: C901, CCR001 if state['BackpackJSON']: entry = state['BackpackJSON'] - # Send interesting events to EDSM - if ( - config.get_int('edsm_out') and not is_beta and not this.multicrew and credentials(cmdr) and - entry['event'] not in this.discardedEvents - ): + # Queue all events to send to EDSM. worker() will take care of dropping EDSM discarded events + if config.get_int('edsm_out') and not is_beta and not this.multicrew and credentials(cmdr): # Introduce transient states into the event transient = { '_systemName': system, From a794d6088f10ba1a10efe9fe1a5563681feaf067 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 5 Aug 2021 15:23:15 +0100 Subject: [PATCH 08/13] plugins/edsm: `cmdr` & `entry` declared & set early, so types now OK --- plugins/edsm.py | 7 ------- 1 file changed, 7 deletions(-) diff --git a/plugins/edsm.py b/plugins/edsm.py index b949670f6..d65678e86 100644 --- a/plugins/edsm.py +++ b/plugins/edsm.py @@ -609,13 +609,6 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently ) break try: - if TYPE_CHECKING: - # Tell the type checker that these two are bound. - # TODO: While this works because of the item check below, these names are still technically unbound - # TODO: in some cases, therefore this should be refactored. - cmdr = "" - entry = {} - if item and entry['event'] not in this.discardedEvents: # TODO: Technically entry can be unbound here. if 'edsm-cmdr-events' in trace_on: logger.trace(f'({cmdr=}, {entry["event"]=}): not in discardedEvents, appending to pending') From f2d7f6a5dfc88fa6e46353c11189d7ecdcc42a67 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 5 Aug 2021 16:13:41 +0100 Subject: [PATCH 09/13] plugins/edsm: Change discarded_events setup, check latest event in should_send() * Ensure we have the discarded_events list *before* starting to consume events. There's the *same* risk as before with EDSM just being down and us queueing up more and more, just now it will be in the worker queue rather than pending. * We need to test for some events in should_send() that are in the discard list, and thus will never be in the `entries` (pending) passwd in, so pass in the name of the latest event as well. --- plugins/edsm.py | 69 ++++++++++++++++++++++++++++--------------------- 1 file changed, 40 insertions(+), 29 deletions(-) diff --git a/plugins/edsm.py b/plugins/edsm.py index d65678e86..e3f5e902e 100644 --- a/plugins/edsm.py +++ b/plugins/edsm.py @@ -14,6 +14,7 @@ import tkinter as tk from queue import Queue from threading import Thread +from time import sleep from typing import TYPE_CHECKING, Any, List, Literal, Mapping, MutableMapping, Optional, Set, Tuple, Union import requests @@ -35,6 +36,7 @@ def _(x: str) -> str: EDSM_POLL = 0.1 _TIMEOUT = 20 +DISCARDED_EVENTS_SLEEP = 10 class This: @@ -43,7 +45,7 @@ class This: def __init__(self): self.session: requests.Session = requests.Session() self.queue: Queue = Queue() # Items to be sent to EDSM by worker thread - self.discardedEvents: Set[str] = [] # List discarded events from EDSM + self.discarded_events: Set[str] = [] # List discarded events from EDSM self.lastlookup: requests.Response # Result of last system lookup # Game state @@ -574,13 +576,31 @@ def cmdr_data(data: CAPIData, is_beta: bool) -> None: if 'edsm' in debug_senders: TARGET_URL = f'http://{DEBUG_WEBSERVER_HOST}:{DEBUG_WEBSERVER_PORT}/edsm' -# Worker thread + +def get_discarded_events_list() -> None: + """Retrieve the list of to-discard events from EDSM.""" + try: + r = this.session.get('https://www.edsm.net/api-journal-v1/discard', timeout=_TIMEOUT) + r.raise_for_status() + this.discarded_events = set(r.json()) + + this.discarded_events.discard('Docked') # should_send() assumes that we send 'Docked' events + if not this.discarded_events: + logger.warning( + 'Unexpected empty discarded events list from EDSM: ' + f'{type(this.discarded_events)} -- {this.discarded_events}' + ) + + except Exception as e: + logger.warning('Exception whilst trying to set this.discarded_events:', exc_info=e) def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently """ Handle uploading events to EDSM API. + Target function of a thread. + Processes `this.queue` until the queued item is None. """ logger.debug('Starting...') @@ -589,6 +609,14 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently cmdr: str = "" entry: Mapping[str, Any] = {} + while not this.discarded_events: + get_discarded_events_list() + if this.discarded_events: + break + + sleep(DISCARDED_EVENTS_SLEEP) + + logger.debug('Got "events to discard" list, commencing queue consumption...') while True: item: Optional[Tuple[str, Mapping[str, Any]]] = this.queue.get() if item: @@ -609,30 +637,13 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently ) break try: - if item and entry['event'] not in this.discardedEvents: # TODO: Technically entry can be unbound here. + if item and entry['event'] not in this.discarded_events: if 'edsm-cmdr-events' in trace_on: - logger.trace(f'({cmdr=}, {entry["event"]=}): not in discardedEvents, appending to pending') + logger.trace(f'({cmdr=}, {entry["event"]=}): not in discarded_events, appending to pending') pending.append(entry) - # Get list of events to discard - if not this.discardedEvents: - r = this.session.get('https://www.edsm.net/api-journal-v1/discard', timeout=_TIMEOUT) - r.raise_for_status() - this.discardedEvents = set(r.json()) - - this.discardedEvents.discard('Docked') # should_send() assumes that we send 'Docked' events - if not this.discardedEvents: - logger.error( - 'Unexpected empty discarded events list from EDSM. Bailing out of send: ' - f'{type(this.discardedEvents)} -- {this.discardedEvents}' - ) - continue - - # Filter out unwanted events - pending = list(filter(lambda x: x['event'] not in this.discardedEvents, pending)) - - if should_send(pending): + if should_send(pending, entry['event']): if 'edsm-cmdr-events' in trace_on: logger.trace(f'({cmdr=}, {entry["event"]=}): should_send() said True') pendings = [f"{p}\n" for p in pending] @@ -736,11 +747,11 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently # LANG: EDSM Plugin - Error connecting to EDSM API plug.show_error(_("Error: Can't connect to EDSM")) - if entry['event'].lower() == 'shutdown': - # Game shutdown so we MUST not hang on to pending + if entry['event'].lower() in ('shutdown', 'commander', 'fileheader'): + # Game shutdown or new login so we MUST not hang on to pending pending = [] if 'edsm-cmdr-events' in trace_on: - logger.trace('Blanked pending because of shutdown event') + logger.trace(f'Blanked pending because of event: {entry["event"]}') if closing: logger.debug('closing, so returning.') @@ -749,7 +760,7 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently logger.debug('Done.') -def should_send(entries: List[Mapping[str, Any]]) -> bool: # noqa: CCR001 +def should_send(entries: List[Mapping[str, Any]], event: str) -> bool: # noqa: CCR001 """ Whether or not any of the given entries should be sent to EDSM. @@ -757,9 +768,9 @@ def should_send(entries: List[Mapping[str, Any]]) -> bool: # noqa: CCR001 :return: bool indicating whether or not to send said entries """ # We MUST flush pending on logout, in case new login is a different Commander - if any(e for e in entries if e['event'] == 'Shutdown'): + if event.lower() in ('shutdown', 'fileheader'): if 'edsm-cmdr-events' in trace_on: - logger.trace('True because Shutdown') + logger.trace(f'True because {event=}') return True @@ -807,7 +818,7 @@ def should_send(entries: List[Mapping[str, Any]]) -> bool: # noqa: CCR001 logger.trace(f'{entry["event"]=}, {this.newgame_docked=}') if 'edsm-cmdr-events' in trace_on: - logger.trace(f'False as default: {entry["event"]=}, {this.newgame_docked=}') + logger.trace(f'False as default: {this.newgame_docked=}') return False From 64f97accc0dbb0c7030863a8ef9c721582bdc1af Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 5 Aug 2021 16:22:46 +0100 Subject: [PATCH 10/13] plugins/edsm: Only try to send if pending isn't empty This prevents literally sending an empty data to EDSM if we trigger sending due to Shutdown. --- plugins/edsm.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/plugins/edsm.py b/plugins/edsm.py index e3f5e902e..b0850921d 100644 --- a/plugins/edsm.py +++ b/plugins/edsm.py @@ -643,7 +643,7 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently pending.append(entry) - if should_send(pending, entry['event']): + if pending and should_send(pending, entry['event']): if 'edsm-cmdr-events' in trace_on: logger.trace(f'({cmdr=}, {entry["event"]=}): should_send() said True') pendings = [f"{p}\n" for p in pending] From 7a71fc8e1436cda13d6ef2030529061968596e41 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 5 Aug 2021 16:40:11 +0100 Subject: [PATCH 11/13] plugins/edsm: Protect discarded_events loop against shutdown --- plugins/edsm.py | 19 +++++++++++++++---- 1 file changed, 15 insertions(+), 4 deletions(-) diff --git a/plugins/edsm.py b/plugins/edsm.py index b0850921d..30340925a 100644 --- a/plugins/edsm.py +++ b/plugins/edsm.py @@ -43,6 +43,8 @@ class This: """Holds module globals.""" def __init__(self): + self.shutting_down = False # Plugin is shutting down. + self.session: requests.Session = requests.Session() self.queue: Queue = Queue() # Items to be sent to EDSM by worker thread self.discarded_events: Set[str] = [] # List discarded events from EDSM @@ -198,7 +200,8 @@ def plugin_stop() -> None: """Stop this plugin.""" logger.debug('Signalling queue to close...') # Signal thread to close and wait for it - this.queue.put(None) + this.shutting_down = True + this.queue.put(None) # Still necessary to get `this.queue.get()` to unblock this.thread.join() # type: ignore this.thread = None this.session.close() @@ -610,6 +613,10 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently entry: Mapping[str, Any] = {} while not this.discarded_events: + if this.shutting_down: + logger.debug(f'returning from discarded_events loop due to {this.shutting_down=}') + return + get_discarded_events_list() if this.discarded_events: break @@ -618,16 +625,20 @@ def worker() -> None: # noqa: CCR001 C901 # Cant be broken up currently logger.debug('Got "events to discard" list, commencing queue consumption...') while True: + if this.shutting_down: + logger.debug(f'{this.shutting_down=}, so setting closing = True') + closing = True + item: Optional[Tuple[str, Mapping[str, Any]]] = this.queue.get() if item: (cmdr, entry) = item + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'De-queued ({cmdr=}, {entry["event"]=})') else: logger.debug('Empty queue message, setting closing = True') closing = True # Try to send any unsent events before we close - - if 'edsm-cmdr-events' in trace_on: - logger.trace(f'De-queued ({cmdr=}, {entry["event"]=})') + entry = {'event': 'ShutDown'} # Dummy to allow for `entry['event']` below retrying = 0 while retrying < 3: From ca87c061a19df2face4310b90b3ad56e6c963763 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 5 Aug 2021 16:50:02 +0100 Subject: [PATCH 12/13] Contributing: Document `--trace-on` code and usage --- Contributing.md | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/Contributing.md b/Contributing.md index e1086de74..7240195b7 100644 --- a/Contributing.md +++ b/Contributing.md @@ -376,6 +376,22 @@ In addition to that we utilise one of the user-defined levels as: command-line argument and `.bat` file for users to enable it. It cannot be selected from Settings in the UI. + As well as just using bare `logger.trace(...)` you can also gate it to only + log if asked to at invocation time by utilising the `--trace-on ...` + command-line argument. e.g. + `EDMarketConnector.py --trace --trace-on edsm-cmdr-events`. Note how you + still need to include `--trace`. The code to check and log would be like: + + ```python + from config import trace_on + + if 'edsm-cmdr-events' in trace_on: + logger.trace(f'De-queued ({cmdr=}, {entry["event"]=})') + ``` + + This way you can set up TRACE logging that won't spam just because of + `--trace` being used. + --- ## Use fstrings, not modulo-formatting or .format From c398be9b5ca200f01c947ad63d337dce4b66af8d Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 5 Aug 2021 17:04:44 +0100 Subject: [PATCH 13/13] Contributing: Document `--debug-send ...` code and usage --- Contributing.md | 34 +++++++++++++++++++++++++++++++++- 1 file changed, 33 insertions(+), 1 deletion(-) diff --git a/Contributing.md b/Contributing.md index 7240195b7..50682e641 100644 --- a/Contributing.md +++ b/Contributing.md @@ -225,7 +225,39 @@ Adding `--trace` to a `pytest` invocation causes it to drop into a [`pdb`](https://docs.python.org/3/library/pdb.html) prompt for each test, handy if you want to step through the testing code to be sure of anything. -Otherwise, see the [pytest documentation](https://docs.pytest.org/en/stable/contents.html). +Otherwise, see the [pytest documentation](https://docs.pytest.org/en/stable/contents.html). + +--- +## Debugging network sends + +Rather than risk sending bad data to a remote service, even if only through +repeatedly sending the same data you can cause such code to instead send +through a local web server and thence to a log file. + +1. This utilises the `--debug-sender ...` command-line argument. The argument + to this is free-form, so there's nothing to edit in EDMarketConnector.py + in order to support a new target for this. +2. The debug web server is set up globally in EDMarketConnector.py. +3. In code where you want to utilise this you will need at least something + like this (taken from some plugins/edsm.py code): + +```python +from config import debug_senders +from edmc_data import DEBUG_WEBSERVER_HOST, DEBUG_WEBSERVER_PORT + +TARGET_URL = 'https://www.edsm.net/api-journal-v1' +if 'edsm' in debug_senders: + TARGET_URL = f'http://{DEBUG_WEBSERVER_HOST}:{DEBUG_WEBSERVER_PORT}/edsm' + +... + r = this.session.post(TARGET_URL, data=data, timeout=_TIMEOUT) +``` + + Be sure to set a URL path in the `TARGET_URL` that denotes where the data + would normally be sent to. +4. The output will go into a file in `%TEMP%\EDMarketConnector\http_debug` + whose name is based on the path component of the URL. In the code example + above it will come out as `edsm.log` due to how `TARGET_URL` is set. ---