From 0e80c76cb564771465f61825e694227dcc3be312 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 6 Jan 2022 13:07:53 +0000 Subject: [PATCH 1/5] Gateway: Set bottle request limit to 1MiB --- src/eddn/Gateway.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/eddn/Gateway.py b/src/eddn/Gateway.py index 63d10d7..028e2f7 100644 --- a/src/eddn/Gateway.py +++ b/src/eddn/Gateway.py @@ -21,7 +21,9 @@ from eddn.core.Validator import Validator, ValidationSeverity from gevent import monkey monkey.patch_all() +import bottle from bottle import Bottle, run, request, response, get, post +bottle.BaseRequest.MEMFILE_MAX = 1024 * 1024 # 1MiB, default is/was 100KiB app = Bottle() logger = logging.getLogger(__name__) From 377bdd3833a721fc639376308745b17c2f248465 Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 6 Jan 2022 13:54:33 +0000 Subject: [PATCH 2/5] Gateway: Add logging per Accepted request Actually some logging was already there, just the logger had never been set up properly, but then I decided to make the format of this message more useful. --- src/eddn/Gateway.py | 25 ++++++++++++++++++++++--- 1 file changed, 22 insertions(+), 3 deletions(-) diff --git a/src/eddn/Gateway.py b/src/eddn/Gateway.py index 028e2f7..93d22bc 100644 --- a/src/eddn/Gateway.py +++ b/src/eddn/Gateway.py @@ -27,6 +27,10 @@ bottle.BaseRequest.MEMFILE_MAX = 1024 * 1024 # 1MiB, default is/was 100KiB app = Bottle() logger = logging.getLogger(__name__) +logger.setLevel(logging.INFO) +logger.addHandler(logging.StreamHandler()) +logger.info('Made logger') + # This socket is used to push market data out to the Announcers over ZeroMQ. context = zmq.Context() @@ -151,10 +155,25 @@ def parse_and_error_handle(data): # Sends the parsed message to the Relay/Monitor as compressed JSON. gevent.spawn(push_message, parsed_message, parsed_message['$schemaRef']) - logger.info("Accepted %s upload from %s" % ( - parsed_message, get_remote_address() - )) + + try: + logger.info('Accepted (%d, "%s", "%s", "%s", "%s", "%s") upload from %s' % ( + request.content_length, + parsed_message['header']['uploaderID'], + parsed_message['header']['softwareName'], + parsed_message['header']['softwareVersion'], + parsed_message['$schemaRef'], + parsed_message['message']['event'] if '/journal' in + parsed_message['$schemaRef'] else '-', + get_remote_address() + )) + + except Exception as e: + print('Logging of Accepted request failed: %s' % (e.message)) + pass + return 'OK' + else: response.status = 400 statsCollector.tally("invalid") From 1371f71217286c2cb2f26ea0f7040fa28919922b Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 6 Jan 2022 14:06:59 +0000 Subject: [PATCH 3/5] Gateway: Set up proper logger formatting For some reason the milliseconds portion of the %S timestamp is using a comma for decimals separator, despite 'locale' saying we're set to (US) English. /tableflip --- src/eddn/Gateway.py | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/src/eddn/Gateway.py b/src/eddn/Gateway.py index 93d22bc..9423c3b 100644 --- a/src/eddn/Gateway.py +++ b/src/eddn/Gateway.py @@ -28,7 +28,14 @@ app = Bottle() logger = logging.getLogger(__name__) logger.setLevel(logging.INFO) -logger.addHandler(logging.StreamHandler()) +__logger_channel = logging.StreamHandler() +__logger_formatter = logging.Formatter( + '%(asctime)s - %(levelname)s - %(module)s:%(lineno)d: %(message)s' +) +__logger_formatter.default_time_format = '%Y-%m-%d %H:%M:%S' +__logger_formatter.default_msec_format = '%s.%03d' +__logger_channel.setFormatter(__logger_formatter) +logger.addHandler(__logger_channel) logger.info('Made logger') From 9f219da6a6cafba3d1b09fda2703270a401744cb Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 6 Jan 2022 17:36:39 +0000 Subject: [PATCH 4/5] Gateway: Expand on logging for interpretation of errors This includes logging the *full* (uncompressed) message if it fails to parse as JSON. --- src/eddn/Gateway.py | 94 +++++++++++++++++++++++++++++++++++++++------ 1 file changed, 83 insertions(+), 11 deletions(-) diff --git a/src/eddn/Gateway.py b/src/eddn/Gateway.py index 9423c3b..96cb90e 100644 --- a/src/eddn/Gateway.py +++ b/src/eddn/Gateway.py @@ -51,6 +51,37 @@ statsCollector = StatsCollector() statsCollector.start() +def extract_message_details(parsed_message): + uploader_id = '<>' + software_name = '<>' + software_version = '<>' + schema_ref = '<>' + journal_event = '<>' + + if 'header' in parsed_message: + if 'uploaderID' in parsed_message['header']: + uploader_id = parsed_message['header']['uploaderID'] + + if 'softwareName' in parsed_message['header']: + software_name = parsed_message['header']['softwareName'] + + if 'softwareVersion' in parsed_message['header']: + software_version = parsed_message['header']['softwareVersion'] + + if '$schemaRef' in parsed_message: + schema_ref = parsed_message['$schemaRef'] + + + if '/journal/' in schema_ref: + if 'message' in parsed_message: + if 'event' in parsed_message['message']: + journal_event = parsed_message['message']['event'] + + else: + journal_event = '-' + + return uploader_id, software_name, software_version, schema_ref, journal_event + def configure(): # Get the list of transports to bind from settings. This allows us to PUB # messages to multiple announcers over a variety of socket types @@ -144,9 +175,24 @@ def parse_and_error_handle(data): ) as exc: # Something bad happened. We know this will return at least a # semi-useful error message, so do so. + try: + logger.error('Error - JSON parse failed (%d, "%s", "%s", "%s", "%s", "%s") from %s:\n%s\n' % ( + request.content_length, + '<>', + '<>', + '<>', + '<>', + '<>', + get_remote_address(), + data + )) + + except Exception as e: + print('Logging of "JSON parse failed" failed: %s' % (e.message)) + pass + response.status = 400 - logger.error("Error to %s: %s" % (get_remote_address(), exc.message)) - return str(exc) + return 'FAIL: ' + str(exc) # Here we check if an outdated schema has been passed if parsed_message["$schemaRef"] in Settings.GATEWAY_OUTDATED_SCHEMAS: @@ -164,14 +210,10 @@ def parse_and_error_handle(data): gevent.spawn(push_message, parsed_message, parsed_message['$schemaRef']) try: - logger.info('Accepted (%d, "%s", "%s", "%s", "%s", "%s") upload from %s' % ( + uploader_id, software_name, software_version, schema_ref, journal_event = extract_message_details(parsed_message) + logger.info('Accepted (%d, "%s", "%s", "%s", "%s", "%s") from %s' % ( request.content_length, - parsed_message['header']['uploaderID'], - parsed_message['header']['softwareName'], - parsed_message['header']['softwareVersion'], - parsed_message['$schemaRef'], - parsed_message['message']['event'] if '/journal' in - parsed_message['$schemaRef'] else '-', + uploader_id, software_name, software_version, schema_ref, journal_event, get_remote_address() )) @@ -182,6 +224,19 @@ def parse_and_error_handle(data): return 'OK' else: + try: + uploader_id, software_name, software_version, schema_ref, journal_event = extract_message_details(parsed_message) + logger.error('Failed Validation "%s" (%d, "%s", "%s", "%s", "%s", "%s") from %s' % ( + str(validationResults.messages), + request.content_length, + uploader_id, software_name, software_version, schema_ref, journal_event, + get_remote_address() + )) + + except Exception as e: + print('Logging of Failed Validation failed: %s' % (e.message)) + pass + response.status = 400 statsCollector.tally("invalid") return "FAIL: " + str(validationResults.messages) @@ -192,17 +247,34 @@ def upload(): try: # Body may or may not be compressed. message_body = get_decompressed_message() + except zlib.error as exc: # Some languages and libs do a crap job zlib compressing stuff. Provide # at least some kind of feedback for them to try to get pointed in # the correct direction. response.status = 400 - logger.error("gzip error with %s: %s" % (get_remote_address(), exc.message)) + try: + logger.error('gzip error (%d, "%s", "%s", "%s", "%s", "%s") from %s' % ( + request.content_length, + '<>', + '<>', + '<>', + '<>', + '<>', + get_remote_address() + )) + + except Exception as e: + print('Logging of "gzip error" failed: %s' % (e.message)) + pass + return exc.message + except MalformedUploadError as exc: # They probably sent an encoded POST, but got the key/val wrong. response.status = 400 - logger.error("Error to %s: %s" % (get_remote_address(), exc.message)) + logger.error("MalformedUploadError from %s: %s" % (get_remote_address(), exc.message)) + return exc.message statsCollector.tally("inbound") From 1134a6c9b46baf5704029e2ed3167661015c9a8f Mon Sep 17 00:00:00 2001 From: Athanasius Date: Thu, 6 Jan 2022 17:39:01 +0000 Subject: [PATCH 5/5] Gateway: Only log first 512 characters of invalid JSON Don't want to spam the logs with up to 1MiB per bad message. --- src/eddn/Gateway.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/eddn/Gateway.py b/src/eddn/Gateway.py index 96cb90e..9aee4f5 100644 --- a/src/eddn/Gateway.py +++ b/src/eddn/Gateway.py @@ -184,7 +184,7 @@ def parse_and_error_handle(data): '<>', '<>', get_remote_address(), - data + data[:512] )) except Exception as e: