| Peter | |
| Apr 11 2023, 9:00 AM |
| F36946925: Screenshot 2023-04-11 at 10.58.56.png | |
| Apr 11 2023, 9:00 AM |
As reported by @Krinkle we still get some PaintTiming events some days after the extension was updated:
https://grafana.wikimedia.org/d/000000326/navigation-timing-alerts?orgId=1&refresh=5m&viewPanel=56
Lets look at the raw data and see what we can find.
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Resolved | • BAbiola-WMF | T328256 Move painttiming metrics to navtiming schema | |||
| Invalid | Peter | T334452 PaintTiming events keeps coming after the Navigation Timing extension was updated |
Did a quick look and could see user agent "Apache-HttpClient/4.5.12" sending dirty data with example names etc. There's some events that has the date before we did the switch client_dt":"2020-04-02..." but then the other timestamp is today "dt":"2023-04-11", that seems to happen for both an obvious bot also for requests that looks more real.
The events from Apache-HttpClient are actually "canary" events that are synthesised by the EventGate system to health-check the various layers of their infrastructure. Our python processor skips these automatically so we never see them there.
I was looking a a different event stream yesterday (to remove left-over navtiming code for eventlogging_FeaturePolicyViolation). This schema has not been in use for several years, and we produce and consume exactly zero events. Opening the raw stream shows this particular event repeated every 15min as the only thing there:
krinkle@stat1004.eqiad.wmnet$ kafkacat -C -b 'kafka-jumbo1004.eqiad.wmnet,kafka-jumbo1005.eqiad.wmnet' -t eventlogging_FeaturePolicyViolation -o '-10'
{"event":{"pageviewToken":"example_token","url":"example_url","featureId":"example_feature"},"meta":{"id":"b0caf18d-6c7f-4403-947d-2712bbe28610","stream":"eventlogging_FeaturePolicyViolation","domain":"canary","dt":"2023-04-12T04:00:06.774Z","request_id":"a0f6ec03-ad54-4fb9-a581-e0dea759563e"},"dt":"2020-04-02T19:11:20.942Z","client_dt":"2020-04-02T19:11:20.942Z","$schema":"/analytics/legacy/featurepolicyviolation/1.0.0","schema":"FeaturePolicyViolation","http":{"request_headers":{"user-agent":"Apache-HttpClient/4.5.12 (Java/1.8.0_362)"}}}
I don't know what the official way to identify these events is. I believe that Apache user agent is the generic default for the Java program in charge of creating these, so that would not be unique to this purpose. Other random Java programs in the world would likely share the same UA. The domain: "canary" key is a fairly strong signal. The other notable detail is that the event subkey follows our schema but with required fields only, with each key set as`$key: "example_".$key" for example url: "exampe_url", token: "example_token".
If these are the only entries in a stream, with nothing else between them, then that is equivalent to the stream being unused/empty.
Afaik the counter we display in Graphite there is from our navtiming processor, though, so that's probably after the canary events are filtered out.