Closed Bug 1592012 Opened 6 years ago Closed 6 years ago

Investigate spike in payload/info/sessionLength validation errors in the Main Ping

Categories

(Data Platform and Tools :: Monitoring & Alerting, task)

Product:
Data Platform and Tools
Component:
Monitoring & Alerting
Type:
task
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED INACTIVE

People

(Reporter: frank, Assigned: klukas)

References

(Blocks 1 open bug)

Details

(Whiteboard: [dataquality])

See this dashboard for the errors themselves.

This bug is for breaking down what types of errors these are, and the cause of the values of these errors. For example, are they negative, truncated, or just malformed?

We can then decide on any of the following remediation:

  • Ignoring this as a valid error
    - Updating the schema to allow these kinds of values through
    - Updating the client to prevent this problem
    - Change the pipeline to handle this differently, e.g. cocercion

There has been a large spike in sessionLength errors due to invalid session lengths. The following three queries show the extent of the error:

Count the number of errors with sessionLength in them. This number is significant (about 3m per day).
https://console.cloud.google.com/bigquery?project=moz-fx-data-shared-prod&organizationId=442341870013&j=bq:US:bquxjob_63195634_16eec5eb507&page=queryresults

SELECT
  DATE(submission_timestamp) AS date,
  error_message,
  exception_class,
  COUNT(*)
FROM
  `moz-fx-data-shar-nonprod-efed.payload_bytes_error.telemetry`
WHERE
  DATE(submission_timestamp) >= date '2019-12-01'
  AND document_type = 'main'
  AND error_message LIKE '%#/payload/info/sessionLength:%'
GROUP BY
  1,
  2,
  3
ORDER BY
  4 DESC

Which versions are predominant in the errors? Firefox 71.0, release, build_id 20191202093317.

https://console.cloud.google.com/bigquery?project=moz-fx-data-shared-prod&organizationId=442341870013&j=bq:US:bquxjob_59efa6c_16eec5c8eb8&page=queryresults

SELECT
  SPLIT(uri, "/")[
OFFSET
  (6)] AS version,
  SPLIT(uri, "/")[
OFFSET
  (7)] AS channel,
  SPLIT(uri, "/")[
OFFSET
  (8)] AS build_id,
  COUNT(*) AS n_documents,
  COUNT(DISTINCT SPLIT(uri, "/")[
  OFFSET
    (3)]) AS n_distinct_documents
FROM
  `moz-fx-data-shar-nonprod-efed.payload_bytes_error.telemetry`
WHERE
  DATE(submission_timestamp) >= date '2019-12-01'
  AND document_type = 'main'
  AND error_message LIKE '%#/payload/info/sessionLength:%'
GROUP BY
  1,
  2,
  3
ORDER BY
  4 DESC

What do the session lengths look like in the payloads? It turns out to be large, negative values.
https://console.cloud.google.com/bigquery?project=moz-fx-data-shared-prod&organizationId=442341870013&j=bq:US:bquxjob_426b3d5b_16eec3827ca&page=queryresults

SELECT
  approx_quantiles(json_EXTRACT(udf_js.gunzip(payload),
    "$.payload.info.sessionLength"), 10)
FROM
  `moz-fx-data-shar-nonprod-efed.payload_bytes_error.telemetry`
WHERE
  DATE(submission_timestamp) >= date '2019-12-01'
  AND document_type = 'main'
  AND error_message LIKE '%#/payload/info/sessionLength:%'
  AND SPLIT(uri, "/")[
OFFSET
  (8)] = '20191202093317'
LIMIT
  1000

It seems to follow the update uptake curve for that release. I'd be interested to see if this is at most one ping per client, or if there is a sizable population of clients sending multiple of these.

This seems to be spread out over the population, I've written another query to check:

SELECT
  date(submission_timestamp) as date,
  count(distinct json_EXTRACT(udf_js.gunzip(payload), "$.clientId")) as n_clients,
  count(*) as n_documents
FROM
  `moz-fx-data-shar-nonprod-efed.payload_bytes_error.telemetry`
WHERE
  DATE(submission_timestamp) >= date '2019-12-01'
  AND document_type = 'main'
  AND error_message LIKE '%#/payload/info/sessionLength:%'
  AND SPLIT(uri, "/")[OFFSET(8)] = '20191202093317'
group by 1
order by 1

Row	date	n_clients	n_documents
1	2019-12-02	6	6
2	2019-12-03	1757	1795
3	2019-12-04	10394	10786
4	2019-12-05	13113	13553
5	2019-12-06	28756	29407
6	2019-12-07	23794	24369
7	2019-12-08	22829	23273
8	2019-12-09	35857	36653

Note that this query is based on the non-prod project, which is a 1% sample of documents.

Anthony noticed that all of these are coming from Windows users. Hey Robert, did something new with Windows updates ride in 71?

Flags: needinfo?(robert.strong.bugs)

Hi Chris, are you referring to something that would cause "session lengths" to be "large, negative values"? If so, nothing app update related that I can think of though there might be something outside of app update that caused this.

Flags: needinfo?(robert.strong.bugs) → needinfo?(chutten)

Yeah, that was to what I was referring. I was hoping there was some Update Agent shenanigans in the work that would somehow muck with when the browser thinks it was launched the first time after update.

Flags: needinfo?(chutten)

Sorry, nothing in the way app update launches Firefox has changed that I can think of. Maybe this has something to do with the launcher (shot in the dark and I only know of its existence).

Launcher? I remember :aklotz knowing things about that.

Flags: needinfo?(aklotz)

I don't see how the launcher process could be affecting anything here...

sessionLength's computation is really straightforward, but it depends on a monotonic time calculated using Timestamp::NowLoRes and Timestamp::ProcessCreation.

Anthony, is telemetry.process_creation_timestamp_inconsistent set in these negative-sessionLength-having pings? There don't appear to be any in the sample of telemetry.main I've looked into.

Flags: needinfo?(aklotz)

There don't appear to be any appearances of process_creation_timestamp_inconsistent in the rejected pings either. In general, the inconsistent timestamp probe is rare with 37 instances in the last 3 months.

Which means TimeStamp is convinced that the values it's giving us are consistent.

*loses himself into win32 api documentation* There doesn't appear to be any obvious footgun in the APIs being used. And even if we were sandboxed into not being able to get the process creation timestamp (you need specific permission), that'd mean we'd just be getting largish positive values (the value of NowLoRes) because overflow is frankly unlikely given the width of the datatypes involved (64bits across the board).

It seemed more likely that we were getting a NowLoRes smaller than ProcessCreation. This could happen, I suppose, due to resolution, I guess, but the advertised resolution of NowLoRes on Windows is typically about 10-16ms so that would mean that the sessionLength was less than, say, 20ms long.

And that doesn't hold up to the quantiles you posted earlier which range from -1B to -9.5B (ish). The bottom end of the range fits into 32 bits, but the upper end doesn't. And the durations we're off by don't make sense either, being on the order of years.

Absolutely none of this makes sense to me, and I'm running out of experts to stunt in and explain how computers are this weird All The Time and isn't it funny we're only noticing that Now.

There is bug 1601796, but it doesn't explain the spike.

This seems like the same issue as bug 1514392, unfortunately :janerik and I didn't come to any definitive conclusions on what was happening there...

Blocks: 1602521

Proposal to allow negative session lengths

Given that we have not yet found a root cause, we need to consider how to work around the issue.

There is likely more harm caused by having these pings rejected (which affects nearly every desktop analysis) vs. allowing in negative values for sessionLength. It's my understanding that sessionLength is generally considered unreliable and not suitable for analysis already (activeTicks is the better alternative) so any analysis relying on sessionLength is already vulnerable to messy data.

The best way forward looks to be relaxing the schema so that negative values are allowed. We can additionally update the user-facing view (telemetry.main) to show null wherever the sessionLength value is negative. We would then backfill from the errors table to restore the missing pings and rerun downstream ETL.

I will plan to discuss with Data Science a bit before we move forward.

I held a discussion about this bug at today's Data Science team meeting. Opinions on how best to handle this are not uniform, but consensus is that the proposed way forward here is the least bad response. In particular, we will allow negative values but make them null in user-facing views and make sure ETL queries also drop the negative values. Data scientists and other sophisticated data users can still look at the underlying tables as needed to better understand the negative values.

PR to allow negative values: https://github.com/mozilla-services/mozilla-pipeline-schemas/pull/474

Assignee: nobody → jklukas

PR for nulling negative sessionLengths in user-facing views: https://github.com/mozilla/bigquery-etl/pull/649

The first day with over 1 million rejected pings is 2019-12-04. The last date with rejected pings is 2020-01-09. So the backfill range will be 2019-12-04 to 2020-01-09.

This data is backfilled to telemetry.main and I'll work on rerunning ETL later this week.

Blocks: 1609465

I've backfill main_summary and clients_daily. I plan to finish remaining ETL backfills today.

ETL backfills are complete. Discussion has moved to https://bugzilla.mozilla.org/show_bug.cgi?id=1609465 so I think we should close this bug.

Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INACTIVE
Whiteboard: [data-platform-health]
Whiteboard: [data-platform-health] → [data-quality]
Whiteboard: [data-quality] → [dataquality]
You need to log in before you can comment on or make changes to this bug.