Draft: Migrate to OpenTelemetry tracing

[MadLittleMods]

Migrate to OpenTelemetry tracing

Fix #11850

• Now requires the latest Twisted (22.8.0+) in order for tracing to work
  • From the backend chapter sync last month, it was discussed that it would probably be fine to require the latest Twisted for tracing as it's mostly a tool for us.

Blockers

• Wait for a new Twisted release that includes the contextvars fixes
  • See Draft: Migrate to OpenTelemetry tracing #13400 (comment), Draft: Migrate to OpenTelemetry tracing #13400 (comment)
  • Update: twisted==22.8.0 (2022-09-06) was released 🚀 - need to try it out!
• Use a non-Python Jaeger exporter for production performance (see switch from jaeger-client to opentelemetry #11850 (comment))
  • We can probably adapt https://github.com/erikjohnston/rust-jaeger-python-client to be an OpenTelemetry compatible exporter because it's mostly Jaeger API stuff. Help welcome!
• force_tracing_for_users
  • Discussion: Draft: Migrate to OpenTelemetry tracing #13400 (comment)

Dev notes

poetry run synapse_homeserver --config-path homeserver.yaml

$ poetry cache list
$ poetry cache clear --all pypi

via https://stackoverflow.com/a/70064450/796832

# Stop the current virtualenv if active
$ deactivate

# Find the venv for poetry
$ poetry env info -p
# Remove all the files of the current environment
$ rm -rf $(poetry env info -p)

# Reactivate Poetry shell
$ poetry shell
# Install everything
$ poetry install --extras all

---

$ psql synapse

ALTER TABLE device_lists_outbound_pokes RENAME COLUMN opentracing_context TO tracing_context;
ALTER TABLE device_lists_changes_in_room RENAME COLUMN opentracing_context TO tracing_context;

ALTER TABLE device_lists_outbound_pokes RENAME COLUMN tracing_context TO opentracing_context;
ALTER TABLE device_lists_changes_in_room RENAME COLUMN tracing_context TO opentracing_context;

Typing

Type hints for optional imports:

• https://adamj.eu/tech/2021/12/29/python-type-hints-optional-imports/
  • https://news.ycombinator.com/item?id=29803756
• https://stackoverflow.com/questions/61384752/how-to-type-hint-with-an-optional-import

OpenTelemetry

• https://opentelemetry.io/docs/instrumentation/python/
• https://opentelemetry.io/docs/instrumentation/python/manual/
• https://opentelemetry-python.readthedocs.io/en/latest/api/
• https://opentelemetry-python.readthedocs.io/en/latest/sdk/index.html
• Migrating:
  • https://opentelemetry.io/docs/migration/opentracing/
  • https://opentelemetry-python.readthedocs.io/en/stable/shim/opentracing_shim/opentracing_shim.html
  • Shim source: https://github.com/open-telemetry/opentelemetry-python/tree/c9222bfc18ec91f041c2f0a9eac8560f61dcb338/shim/opentelemetry-opentracing-shim/src/opentelemetry/shim/opentracing_shim
  • opentracing source: https://github.com/opentracing/opentracing-python/tree/master/opentracing
    • tags.py
  • Migrating some references
    • child_of to supplying the context on a OTEL span
    • follows_from references -> links on an OTEL span
    • What's the difference between follows_from and child_of? See https://opentracing.io/specification/
• API docs:
  • https://opentelemetry-python.readthedocs.io/en/stable/
• Typing:
  • Add type hints to opentelemetry-sdk and run as a part of tests open-telemetry/opentelemetry-python#1608

Code:

• synapse/logging/opentracing.py
• synapse/config/tracer.py

OTEL code:

• SpanAttributes (opentelemetry-semantic-conventions/src/opentelemetry/semconv/trace/__init__.py)
• https://github.com/open-telemetry/opentelemetry-python-contrib

Sampling:

• https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/trace/sdk.md#sampling
• https://opentelemetry-python.readthedocs.io/en/latest/sdk/trace.sampling.html
• [feat] Allow additional sampling hooks open-telemetry/oteps#115
• opentracing: https://github.com/jaegertracing/jaeger-client-python#debug-traces-forced-sampling

UDP on macOS (maybe Docker)

Error when using jaeger.thrift over Thrift-compact protocol with UDP on port 6831

homeserver.yaml

tracing:
   # ...
    jaeger_exporter_config:
      agent_host_name: localhost
      agent_port: 6831

2022-08-02 19:37:14,796 - opentelemetry.sdk.trace.export - 360 - ERROR - sentinel - Exception while exporting Span batch.
Traceback (most recent call last):
  File "/Users/eric/Documents/github/element/synapse/.venv/lib/python3.9/site-packages/opentelemetry/sdk/trace/export/__init__.py", line 358, in _export_batch
    self.span_exporter.export(self.spans_list[:idx])  # type: ignore
  File "/Users/eric/Documents/github/element/synapse/.venv/lib/python3.9/site-packages/opentelemetry/exporter/jaeger/thrift/__init__.py", line 219, in export
    self._agent_client.emit(batch)
  File "/Users/eric/Documents/github/element/synapse/.venv/lib/python3.9/site-packages/opentelemetry/exporter/jaeger/thrift/send.py", line 95, in emit
    udp_socket.sendto(buff, self.address)
OSError: [Errno 40] Message too long

2022-08-02 19:45:50,196 - opentelemetry.exporter.jaeger.thrift.send - 87 - WARNING - sentinel - Data exceeds the max UDP packet size; size 94357, max 65000

Fix: open-telemetry/opentelemetry-python#1061 (comment) -> https://www.jaegertracing.io/docs/1.19/client-libraries/#emsgsize-and-udp-buffer-limits -> jaegertracing/jaeger-client-node#124

$ sysctl net.inet.udp.maxdgram
net.inet.udp.maxdgram: 9216
$ sudo sysctl net.inet.udp.maxdgram=65536
net.inet.udp.maxdgram: 9216 -> 65536
$ sysctl net.inet.udp.maxdgram
net.inet.udp.maxdgram: 65536

To make those changes stick between OS reboots, make sure to add it to /etc/sysctl.conf as well:

/etc/sysctl.conf

net.inet.udp.maxdgram=65536

You also have to set udp_split_oversized_batches to split the batches up if they go over the 65k limit set in OTEL
homeserver.yaml

tracing:
    # ...
    jaeger_exporter_config:
      agent_host_name: localhost
      agent_port: 6831
      # Split UDP packets (UDP_PACKET_MAX_LENGTH is set to 65k in OpenTelemetry)
      udp_split_oversized_batches: true

Using thrift over UDP (port 6831) to communicate to the Jaeger agent doesn't seem to work from within a Complement test Docker container. I wonder why this is the case? I was seeing this same behavior with the Jaeger opentracing stuff. Is the UDP connection being over saturated (1065 spans in one trace)? Can the Jaeger agent in Docker not keep up? We see some spans come over but never the main servlet overarching one that is probably the last to be exported. But using the HTTP Jaeger collector endpoint seems to work fine for getting the whole trace (collector_endpoint: "http://localhost:14268/api/traces?format=jaeger.thrift")

TODO

• synapse/logging/scopecontextmanager.py
  • https://github.com/open-telemetry/opentelemetry-python/blob/c9222bfc18ec91f041c2f0a9eac8560f61dcb338/shim/opentelemetry-opentracing-shim/src/opentelemetry/shim/opentracing_shim/__init__.py#L435
• start_active_span_follows_from
• start_active_span_from_edu
• synapse/federation/transport/server/_base.py (search for scope)
• Document config changes
• Update docs docs/tracing.md
• Thrift vs protobuf
  • See Draft: Migrate to OpenTelemetry tracing #13400 (comment)
• Make sure the app runs without errors/warnings
  • Failed to detach context errors (ValueError: <Token var=<ContextVar name='current_context' default={} at 0x111b80cc0> at 0x111b98880> was created in a different Context)
    • See Draft: Migrate to OpenTelemetry tracing #13400 (comment), Draft: Migrate to OpenTelemetry tracing #13400 (comment)
• force_tracing_for_users

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.
  • Feel free to credit yourself, by adding a sentence "Contributed by @github_username." or "Contributed by [Your Name]." to the end of the entry.
• Pull request includes a sign off
• Code style is correct
  (run the linters)

[MadLittleMods]

I don't know what I am doing with the dependencies here. Please double check this stuff.

[MadLittleMods]

When viewing a trace for a servlet, we have the db.{desc} span but the child database spans are missing like db.connection, db.txn, db.query 🤔

Probably need to assert that the parents are set correctly in the tests as well (particularly with deferreds).

[MadLittleMods]

Moving this over from #13440 (comment),

Occasionally, I see spans that have a super massive duration and shows up with 213503982d 8h in the Jaeger UI. Obviously looks like some sort of max duration bug.

The raw data for those spans are the following. Only these spans are messed up and the end_time does not affect any more parent spans before _process_pulled_event.

db.get_partial_state_events

{
    "traceID": "563478e5d75db03e9fc028822fde0649",
    "spanID": "5b63b0172763c5cf",
    "flags": 1,
    "operationName": "db.get_partial_state_events",
    "references": [
        {
            "refType": "CHILD_OF",
            "traceID": "563478e5d75db03e9fc028822fde0649",
            "spanID": "10c9f2a2c50e286f"
        }
    ],
    "startTime": 1659994809436162,
    "duration": 18446744073709517944,
    "tags": [
        // ...
    ],
    "logs": [],
    "processID": "p1",
    "warnings": null
}

_process_pulled_event

{
    "traceID": "563478e5d75db03e9fc028822fde0649",
    "spanID": "6e9ee2608b03b542",
    "flags": 1,
    "operationName": "_process_pulled_event",
    "references": [
        {
            "refType": "CHILD_OF",
            "traceID": "563478e5d75db03e9fc028822fde0649",
            "spanID": "af2c9c8d08284134"
        }
    ],
    "startTime": 1659994809432356,
    "duration": 18446744073709532019,
    "tags": [
        // ...
    ],
    "logs": [],
    "processID": "p1",
    "warnings": null
},

Definitely close to the Python "max int size" (unsigned word, 64 bits): sys.maxsize * 2 + 1 (or 2^64 - 1) -> 18446744073709551615 (via https://stackoverflow.com/questions/7604966/maximum-and-minimum-values-for-ints)

It seems like it's some negative value getting turned into an unsigned integer so it wraps to the end of the value range. But I don't see the math where that can happen yet.

start_time and end_time are calculated by time.time_ns() (_time_ns)

And the Jaeger exporter calculates startTime and duration with this small _nsec_to_usec_round function.

To see if it's just some endTime (0) - startTime (some positive number) = some negative number, type of problem: If we take the Python max value minus the duration we see from _process_pulled_event: 18446744073709551615 - 18446744073709532019 -> 19596 microseconds. TODO: Is that reasonable?

[MadLittleMods]

Closing as our existing OpenTracing setup seems to just work over UDP inside Docker (for Complement tests) on my Linux machine now so I don't have a personal need for this anymore (didn't work properly on macOS).

This is probably best tackled with a fresh PR with some of the learnings from here anyway