Support outputting structured logs in addition to standard logs

[clokep]

This supports outputting structured logs at the same time as "standard" logs by reworking how the structured logging system works to be configurable as part of the standard Python logging config. This unfortunately got very large, but I've been unable to come up with a reasonable plan to split it up. It should be reviewable commit-by-commit, although a couple are still rather large! I can walk through it with someone if that's easiest!

The first commit removes the custom configuration code (synapse.logging._structured) for structured logging, which is no longer necessary.

The main commit converts the JSON log observers into a Formatter and the TCP log observer into a Handler. This is essentially converting from Twisted logging infrastructure to the Python standard library infrastructure. Due to this, the terse JSON code gets simplified since a LogRecord is simpler than the Twisted log events.

After doing that we need to add back support for passing the server_name through to the output via a Filter.

Finally, we update synmark to use the new code, which is fairly invasive. I ended up modifying it to avoid creating a homeserver and only instantiating the logging framework, this should be more realistic for benchmarking.

There's also a couple of clean-up commits, but hopefully those are self-explanatory.

This builds on #8587

Fixes #8588

[clokep]

I should add something to UPGRADE.rst about this as it is a breaking change in the config file format.

[erikjohnston]

I should add something to UPGRADE.rst about this as it is a breaking change in the config file format.

We probably should also throw a helpful exception if we see structured: true in the config?

[erikjohnston]

@clokep What is your intention for producing structured logs? I think the reason for using the twisted logger in the first place was that it has native support structured logging? I guess I'd kinda like to see an example of how we'd actually attach extra metadata to the log lines?

[clokep]

@clokep What is your intention for producing structured logs? I think the reason for using the twisted logger in the first place was that it has native support structured logging? I guess I'd kinda like to see an example of how we'd actually attach extra metadata to the log lines?

@erikjohnston and I had some conversation about this out of band, it seems the intention of the original code was to switch to using the Twisted logging system in places that we want structured logs to make them something like:

log.info("Stuff {stuff} and {things}", stuff=stuff, things=things, extra_data=extra_data)

The Python docs on structured logging don't seem super pretty to use, however.

I think I need to:

1. Investigate how additional info for particular log entries could be included.
2. Include an example in this PR (or have a follow-up ready) where we actually use structured logging.

Erik also asked:

Also, ooi do you know how the stdlib TCP logging handler compares to our custom one?

The code in this PR uses Twisted for the TCP mechanism which should help with ensuring that logging doesn't block the reactor. This is expanded a bit on the issue: #8588 (comment)

[clokep]

I should add something to UPGRADE.rst about this as it is a breaking change in the config file format.

We probably should also throw a helpful exception if we see structured: true in the config?

I added this. 👍

[clokep]

I guess I'd kinda like to see an example of how we'd actually attach extra metadata to the log lines?

7fb5505 (#8607) now includes a test that shows how additional metadata can be attached to log lines. The tl;dr is that the standard extra keyword is used:

The fourth keyword argument is extra which can be used to pass a dictionary which is used to populate the __dict__ of the LogRecord created for the logging event with user-defined attributes. These custom attributes can then be used as you like. For example, they could be incorporated into logged messages.

The example using the Twisted logging above was:

log.info("Stuff {stuff} and {things}", stuff=stuff, things=things, extra_data=extra_data)

This would be become:

logger.info("Stuff %s and %s", stuff, things, extra={"stuff": stuff, "things": things})

Which is a bit more manual, but seems like a reasonable way to get started?

[clokep]

As a summary (since quite a few changes were made):

• 24ab2df was the first commit after review
• Some trivial formatting / style changes were made
• Specific comments were handled and the comment threads resolved above.
• An error is now raised is structured: true is still in the logging config.
• The sample configuration was updated to point to the structured logging docs.
• Tests were reworked a bit to abstract code.
• An additional test for including additional structured data was included.

Open questions:

• Any unresolved comment threads (seems to only be one about including the logging time).
• Whether using extra to include additional information is OK or not.

[erikjohnston]

This broadly looks good. @clokep shall I wait until we've heard back from ops, or do you want to just land this?

[clokep]

This broadly looks good. @clokep shall I wait until we've heard back from ops, or do you want to just land this?

I think I'd prefer to land this as is, I don't think it makes the output structured logs worse than they are now and it does allow running both standard and structured logging at the same time, which is a definite improvement. Additionally, adding more into this PR seems like a bad idea.

I think work left to do includes:

• Coming up with a way to not have to repeat information for the structured logs (e.g. right now it requires the extra dict).
• Switching some of our logging over to include better / more information.
• Adding additional context (from the request?) onto logged messages (besides just the request ID).

[erikjohnston]

We need to remember to yell loudly in the changelog

[clokep]

We need to remember to yell loudly in the changelog

Does the info added to UPGRADE.rst count? 😄

[clokep]

From our conversation off GitHub about making this backwards compatible the following changes were enacted:

• Instead of raising an error if structured: true is seen this kicks off a translation of the config to a compatible config.
• This adds a JsonFormatter, which is the TerseJsonFormatter without the time. (Why is the "terse" formatter less-terse?)
• Updates the upgrade notes and documentation about these changes (including a guide for how to upgrade your config).

The diff is a little funky since I brought back the synapse.logging._structured file which had some code I wanted.