Add fields to better debug where events are being soft_failed

[MadLittleMods]

Add room_id, mxid, and hs fields to better debug where and who events are being soft_failed. We can do aggregations with Elasticsearch and Kibana on these fields.

Follow-up to #10156 (comment)

Testing strategy

1. Enable structured logging in the Sytest Synapse homeserver config,
2. In the formatters property, add a structured key (this key could be named anything) that points to the synapse.logging.TerseJsonFormatter class, lib/SyTest/Homeserver.pm#L220-L224

     formatters => {
        precise => {
           format => "%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s - %(message)s"
        },
   +    structured => {
   +       class => "synapse.logging.TerseJsonFormatter"
   +    }
     },

3. In the handlers property, adjust file handler formatter to point to your structured formatter:

     handlers => {
        file => {
           class => "logging.FileHandler",
   +       formatter => "structured",
           filename => "$hs_dir/$log_type.log",
           filters => ["context"],
           encoding => "utf8"
        }
     },

4. Modify synapse/handlers/federation.py to always soft-fail messages

     try:
         event_auth.check(room_version_obj, event, auth_events=current_auth_events)
   +     raise AuthError(403, "Fake Auth failure")
     except AuthError as e:
         ...

5. ./run-tests.pl tests/50federation/34room-backfill.pl --server-log --stop-on-fail
6. Notice Soft-failing structured log objects with the room_id, mxid, hs properties 🎉

   {"log":"Soft-failing <FrozenEventV3 event_id='$dhqyh6kWWYCzVsc3k4Xh951oiK25va81l5gFB64798w', type='m.room.message', state_key=None> (from 403: Fake Auth failure) because localhost:51321","namespace":"synapse.handlers.federation","level":"WARNING","time":1623484246.69,"request":"PUT-45-!qCOYGPEywmWeSYLrPJ:localhost:8800-$dhqyh6kWWYCzVsc3k4Xh951oiK25va81l5gFB64798w","ip_address":"127.0.0.1","site_tag":"8800","requester":"localhost:51321","authenticated_entity":"localhost:51321","method":"PUT","url":"/_matrix/federation/v1/send/1623484246656","protocol":"HTTP/1.1","user_agent":"Perl + Net::Async::HTTP/0.47","server_name":"localhost:8800","room_id":"!qCOYGPEywmWeSYLrPJ:localhost:8800","mxid":"@__ANON__-3:localhost:51321","hs":"localhost:51321"}
   

Dev notes

How to enable structured logging

1. In your homeserver.yaml, find where your log_config is located
2. Open your log config file you found from your homeserver.yaml in the last step (probably looks something like *.log.config)
3. In the formatters property, add a structured key (this key could be named anything) that points to the synapse.logging.TerseJsonFormatter class

   formatters:
       precise:
           format: '%(asctime)s - %(name)s - %(lineno)d - %(levelname)s - %(request)s - %(message)s'
   +    structured:
   +        class: synapse.logging.TerseJsonFormatter

4. In the handlers property, adjust file handler formatter to point to your structured formatter:

   handlers:
       file:
           class: logging.handlers.TimedRotatingFileHandler
   +        formatter: structured
           filename: /Users/eric/Documents/github/element/synapse/homeserver.log
           when: midnight
           backupCount: 3  # Does not include the current log file.
           encoding: utf8

5. Run the app to generate some logs, python -m synapse.app.homeserver --config-path homeserver.yaml
6. Open the log file and observe the structured logging (a bunch of json objects)

Background and notes behind structured logging

For the future:
If we want to dig deeper into what rooms are soft_failing messages, we could use the Elasticsearch logs and some aggregations (Kibana or raw ES queries). We can add a few fields to the Elasticsearch mapping, room_id, mxid, event_id which should handle the high cardinality(lots of different values) just fine.
It looks like we use Logstash or Filebeat and I assume there is a way we can parse another field out besides message? Maybe https://stackoverflow.com/q/40460830/796832
-- #10156 (comment)

To document my additional findings here;

We can already use logger.info('foo', extra={ "foo": "bar"}) as shown in tests/logging/test_terse_json.py#L64-L74 to add extra fields to the structured logging.

• Docs on structured logging in Synapse: https://github.com/matrix-org/synapse/blob/develop/docs/structured_logging.md

• Improve structured logging: Improve structured logging #8683

  • Record more information into structured logs: Record more information into structured logs #9654

• Use structured logging for EMS: matrix-org/matrix-hosted#1229

• Use structured logging for matrix.org: matrix-org/internal-config#889

• Allow simultaneously enabling structured logging and "standard" logging which was implemented in Support outputting structured logs in addition to standard logs #8607

• List of issues with the z-logging label: https://github.com/matrix-org/synapse/labels/z-logging

-- #10156 (comment)

• "The fourth keyword argument is extra which can be used to pass a dictionary which is used to populate the __dict__ of the LogRecord", https://docs.python.org/3/library/logging.html#logging.Logger.debug
• Defines which properties of the LogRecord are being copied into the structured log JSON, synapse/logging/_terse_json.py#L23-L48

Unused testing commands

1. Start the app, python -m synapse.app.homeserver --config-path homeserver.yaml
2. register_new_matrix_user -c ./homeserver.yaml http://localhost:8008 (test-user1, my-password, not admin)
3. To get an access token for the user you just created, do a login request (note the access_token in the response):

   curl -X POST "http://localhost:8008/_matrix/client/r0/login" \
     -H $'Content-Type: application/json' \
     --data-binary @- << EOF
     {
       "type": "m.login.password",
       "identifier": {
         "type": "m.id.user",
         "user": "test-user1"
       },
       "password": "my-password"
     }
   EOF
   

4. Create a room to post in (note the room_id in the response)

   curl -X POST "http://localhost:8008/_matrix/client/r0/createRoom" \
     -H $'Authorization: Bearer <your_access_token>' \
     -H $'Content-Type: application/json' \
     --data-binary @- << EOF
     {
       "preset": "public_chat",
       "room_alias_name": "thepub",
       "name": "The Grand Duke Pub",
       "topic": "All about happy hour"
     }
   EOF
   

5. Send a message to the room

   curl -X PUT "http://localhost:8008/_matrix/client/r0/rooms/\!kzVUpZOLnmGsiRAsBD:my.synapse.server/send/m.room.message/$(openssl rand -base64 12)"\
     -H $'Authorization: Bearer <your_access_token>' \
     -H $'Content-Type: application/json' \
     --data-binary @- << EOF
     {
       "msgtype": "m.text",
       "body": "asdf"
     }
   EOF
   

6. Get the messages

   curl -X GET \
     -H $'Authorization: Bearer <your_access_token>' \
     "http://localhost:8008/_matrix/client/r0/rooms/\!kzVUpZOLnmGsiRAsBD:my.synapse.server/messages?dir=b&limit=100"
   

Todo

• Turn on structured logging and see if the new properties are in the logs

Pull Request Checklist

• Pull request is based on the develop branch
• Pull request includes a changelog file. The entry should:
  • Be a short description of your change which makes sense to users. "Fixed a bug that prevented receiving messages from other servers." instead of "Moved X method from EventStore to EventWorkerStore.".
  • Use markdown where necessary, mostly for code blocks.
  • End with either a period (.) or an exclamation mark (!).
  • Start with a capital letter.
• Pull request includes a sign off
• Code style is correct (run the linters)

[MadLittleMods]

Useful to log which homeserver is sending all of the bad events

[MadLittleMods]

Useful to know who is sending the bad events

[MadLittleMods]

Useful to know where the bad events are being sent

[MadLittleMods]

For another example of extra, see tests/logging/test_terse_json.py#L64-L74 which adds extra fields to the structured logging objects.

"The fourth keyword argument is extra which can be used to pass a dictionary which is used to populate the __dict__ of the LogRecord", https://docs.python.org/3/library/logging.html#logging.Logger.debug

[richvdh]

lgtm.

Sadly I don't think any of our production deployments use the structured logging system currently, but hopefully that will change one day.

[MadLittleMods]

Thanks for the review and merge @richvdh 🦞

I'm tracking the issues for setting up structured logging on EMS and matrix.org so hopefully they can have some movement!