Logging JSON encoded messages results in an invalid JSON string in log

[0xRand0m]

Example: This statement

self.logger.info("received message: {} ".format(json.loads(msg)))

with msg

{"document": "JOTB is awesome!","es_url": "http://localhost:9200/","index": "jotb"}

results in

{"level": "INFO", "msg": "received message: {"document": "JOTB is awesome!","es_url": "http://localhost:9200/\",\"index\": "jotb"} ", "time": "2019-03-11T07:40:36+0000", "service": "elasticstore"}

The log output should be a valid JSON string without regards to the contents of msg.

[heller-droxit]

Fix logging format for JSON-formatted strings

[heller-droxit]

self.logger.info("received message: {} ".format(json.loads(msg))) seems to work flawlessly, however dumping a JSON dict with self.logger.info("received message: {} ".format(json.dumps(json_dict))) causes the effects described above

[heller-droxit]

The output of the mentioned statement can be considered as expected behaviour.

The BasicLogger (which is used in this case) takes the incoming message, wrapps it into a JSON including meta info and passes directly to the python logging class which handles and logs the whole message. If the core message containing a JSON gets dumped first, (usually) all strings in this JSON are encapsulated with double-ticks ("). If this dumped JSON is then inserted into a string also wrapped with double-ticks using .format() (here at "received message: {}") the inserted JSON string gets escaped wich leads to the placement of \ escape characters before each double-tick in the string. This is therefore not only expected behaviour but is instead useful as the JSON-string would not be correctly parsable if it didn't contain escape characters. To extract the json, the string has to be parsed first, thean the JSON string has to be extracted and then parsed using json.loads(). This makes concatenating dumped JSON strings with other strings complicated to handle.

To increase readability for humans you can just insert the JSON as a dict without having to dump it first: msg_json = {"document": "JOTB is awesome!", "es_url": "http://localhost:9200/", "index": "jotb"} self.logger.info("received message: {} ".format(msg_json)) Resulting in the output: {"level": "INFO", "msg": "received message: {'document': 'JOTB is awesome!', 'es_url': htttp://localhost:9200/', 'index': 'jotb'} ", "time": "2019-05-23T10:02:39+0000", "service": "test"}

To directly place the message JSON into the wrapping log ging JSON you can just log the message JSON dict directly making it easy to read and easy to parse, but loosing the context of "received message":

self.logger.info(msg_json) Output: {"level": "INFO", "msg": {"document": "JOTB is awesome!", "es_url": "http://localhost:9200/", "index": "jotb"}, "time": "2019-05-23T10:02:39+0000", "service": "test"}

A way to avoid this would be to include a separate field in the logging JSON named "description" containing a description of the message passed, leaving the message itself untouched and providing context for the user.

[heller-droxit]

(2) Additional "description" field in logging JSON of BasicLogger

[heller-droxit]

(2) Additional "description" field in logging JSON of BasicLogger