Add metrics to track how often events are soft_failed

[MadLittleMods]

Add metrics to track how often events are soft_failed

Spawned from missing messages we were seeing on matrix.org from a
federated Gitter bridged room, https://gitlab.com/gitterHQ/webapp/-/issues/2770.
The underlying issue in Synapse is tracked by #10066
where the message and join event race and the message is soft_failed before the
join event reaches the remote federated server.

Less soft_failed events = better and usually this should only trigger for events
where people are doing bad things and trying to fuzz and fake everything.

This metric does not track what situation causes the event to be soft_failed but could be used to know how many people roughly are potentially running into #10066.

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)

[anoadragon453]

Thanks for the detailed explanation. Code looks good, though I wonder if a simple counter is the most useful metric here versus something that may give us an idea of how many rooms soft failed events are appearing across.

I'm not sure of a metric type that could be used for that though, so leaving this open for someone to have a second look.

[richvdh]

As @anoadragon453 says, I'm not sure if this will help a great deal, because you don't know where the failures are happening. That said, I don't really think there's a better way to do this, and at least if the soft-failures counter is zero, that gives you an easy way to rule out soft-failure as a problem.

[MadLittleMods]

Thanks for the review passes @anoadragon453 and @richvdh 🕺

I think it's useful to know whether it's happening or not regardless of how.

---

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

[richvdh]

lgtm, thanks!

[MadLittleMods]

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: https://github.com/matrix-org/matrix-hosted/issues/1229
• Use structured logging for matrix.org: https://github.com/matrix-org/internal-config/issues/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

[MadLittleMods]

Created #10168 to add these fields