1432362 - UBSan: -223.106 is outside the range of representable values of type 'unsigned int' in /toolkit/components/telemetry/Telemetry.cpp

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect, P2)

Description

[Tyson Smith [:tsmith]]

This is triggered about a minute after launch when built with -fsanitize=float-cast-overflow

changeset: 400160:20e194b34185

/toolkit/components/telemetry/Telemetry.cpp:1977:36: runtime error: -223.106 is outside the range of representable values of type 'unsigned int'
    #0 0x7f56d260654e in mozilla::Telemetry::AccumulateTimeDelta(mozilla::Telemetry::HistogramID, mozilla::TimeStamp, mozilla::TimeStamp) /toolkit/components/telemetry/Telemetry.cpp:1977:36
    #1 0x7f56c525c9a6 in mozilla::net::nsLoadGroup::TelemetryReportChannel(nsITimedChannel*, bool) /netwerk/base/nsLoadGroup.cpp:998:9
    #2 0x7f56c525b9fa in mozilla::net::nsLoadGroup::RemoveRequest(nsIRequest*, nsISupports*, nsresult) /netwerk/base/nsLoadGroup.cpp:603:13
    #3 0x7f56c5d136ba in mozilla::net::HttpChannelChild::DoOnStopRequest(nsIRequest*, nsresult, nsISupports*) /netwerk/protocol/http/HttpChannelChild.cpp:1264:17
    #4 0x7f56c5d196b3 in mozilla::net::HttpChannelChild::OnStopRequest(nsresult const&, mozilla::net::ResourceTimingStruct const&, mozilla::net::nsHttpHeaderArray const&) /netwerk/protocol/http/HttpChannelChild.cpp:1124:5
    #5 0x7f56c5f36a53 in mozilla::net::ChannelEventQueue::FlushQueue() /netwerk/ipc/ChannelEventQueue.cpp:93:12
    #6 0x7f56c5c6bc4f in mozilla::net::ChannelEventQueue::MaybeFlushQueue() /objdir-ff-ubsan/dist/include/mozilla/net/ChannelEventQueue.h:329:5
    #7 0x7f56c5f440af in mozilla::net::ChannelEventQueue::CompleteResume() /objdir-ff-ubsan/dist/include/mozilla/net/ChannelEventQueue.h:306:5
    #8 0x7f56c5f404a9 in mozilla::net::ChannelEventQueue::ResumeInternal()::CompleteResumeRunnable::Run() /netwerk/ipc/ChannelEventQueue.cpp:161:17
    #9 0x7f56c5015900 in mozilla::SchedulerGroup::Runnable::Run() /xpcom/threads/SchedulerGroup.cpp:395:25
    #10 0x7f56c50529f1 in nsThread::ProcessNextEvent(bool, bool*) /xpcom/threads/nsThread.cpp:1040:14
    #11 0x7f56c508dcca in NS_ProcessNextEvent(nsIThread*, bool) /xpcom/threads/nsThreadUtils.cpp:517:10
    #12 0x7f56c63dc101 in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /ipc/glue/MessagePump.cpp:97:21
    #13 0x7f56c623cfb0 in MessageLoop::Run() /ipc/chromium/src/base/message_loop.cc:299:3
    #14 0x7f56cc6e9bb5 in nsBaseAppShell::Run() /widget/nsBaseAppShell.cpp:157:27
    #15 0x7f56d27cb37d in XRE_RunAppShell() /toolkit/xre/nsEmbedFunctions.cpp:874:22
    #16 0x7f56c63dd128 in mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) /ipc/glue/MessagePump.cpp:269:9
    #17 0x7f56c623cfb0 in MessageLoop::Run() /ipc/chromium/src/base/message_loop.cc:299:3
    #18 0x7f56d27ca8ce in XRE_InitChildProcess(int, char**, XREChildData const*) /toolkit/xre/nsEmbedFunctions.cpp:700:34
    #19 0x517a89 in content_process_main(mozilla::Bootstrap*, int, char**) /browser/app/../../ipc/contentproc/plugin-container.cpp:63:30
    #20 0x517c32 in main /browser/app/nsBrowserApp.cpp:280:18
    #21 0x7f56fd59e1c0 in __libc_start_main /build/glibc-itYbWN/glibc-2.26/csu/../csu/libc-start.c:308
    #22 0x4207a9 in _start (/objdir-ff-ubsan/dist/bin/firefox+0x4207a9)

Comment 1

[Chris H-C :chutten]

Pretty sure this is a direct dupe.

Comment 2

[Tyson Smith [:tsmith]]

This is still happening on changeset: 402372:3df7961bad2c

/toolkit/components/telemetry/Telemetry.cpp:1991:36: runtime error: -633.009 is outside the range of representable values of type 'unsigned int'
    #0 0x7f052e89593e in mozilla::Telemetry::AccumulateTimeDelta(mozilla::Telemetry::HistogramID, mozilla::TimeStamp, mozilla::TimeStamp) /toolkit/components/telemetry/Telemetry.cpp:1991:36
    #1 0x7f0521581896 in mozilla::net::nsLoadGroup::TelemetryReportChannel(nsITimedChannel*, bool) /netwerk/base/nsLoadGroup.cpp:998:9
    #2 0x7f05215808ea in mozilla::net::nsLoadGroup::RemoveRequest(nsIRequest*, nsISupports*, nsresult) /netwerk/base/nsLoadGroup.cpp:603:13
    #3 0x7f052203886a in mozilla::net::HttpChannelChild::DoOnStopRequest(nsIRequest*, nsresult, nsISupports*) /netwerk/protocol/http/HttpChannelChild.cpp:1304:17
    #4 0x7f052203eb63 in mozilla::net::HttpChannelChild::OnStopRequest(nsresult const&, mozilla::net::ResourceTimingStruct const&, mozilla::net::nsHttpHeaderArray const&) /netwerk/protocol/http/HttpChannelChild.cpp:1164:5
    #5 0x7f0522260cb3 in mozilla::net::ChannelEventQueue::FlushQueue() /netwerk/ipc/ChannelEventQueue.cpp:93:12
    #6 0x7f0521f9107f in mozilla::net::ChannelEventQueue::MaybeFlushQueue() /objdir-ff-ubsan/dist/include/mozilla/net/ChannelEventQueue.h:329:5
    #7 0x7f052226e30f in mozilla::net::ChannelEventQueue::CompleteResume() /objdir-ff-ubsan/dist/include/mozilla/net/ChannelEventQueue.h:306:5
    #8 0x7f052226a709 in mozilla::net::ChannelEventQueue::ResumeInternal()::CompleteResumeRunnable::Run() /netwerk/ipc/ChannelEventQueue.cpp:161:17
    #9 0x7f05213334c0 in mozilla::SchedulerGroup::Runnable::Run() /xpcom/threads/SchedulerGroup.cpp:395:25
    #10 0x7f0521370301 in nsThread::ProcessNextEvent(bool, bool*) /xpcom/threads/nsThread.cpp:1040:14
    #11 0x7f05213ad37a in NS_ProcessNextEvent(nsIThread*, bool) /xpcom/threads/nsThreadUtils.cpp:517:10
    #12 0x7f0522708381 in mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /ipc/glue/MessagePump.cpp:97:21
    #13 0x7f0522567090 in MessageLoop::Run() /ipc/chromium/src/base/message_loop.cc:299:3
    #14 0x7f0528981b95 in nsBaseAppShell::Run() /widget/nsBaseAppShell.cpp:157:27
    #15 0x7f052ea5a73d in XRE_RunAppShell() /toolkit/xre/nsEmbedFunctions.cpp:873:22
    #16 0x7f05227093a8 in mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) /ipc/glue/MessagePump.cpp:269:9
    #17 0x7f0522567090 in MessageLoop::Run() /ipc/chromium/src/base/message_loop.cc:299:3
    #18 0x7f052ea59c8e in XRE_InitChildProcess(int, char**, XREChildData const*) /toolkit/xre/nsEmbedFunctions.cpp:699:34
    #19 0x517a89 in content_process_main(mozilla::Bootstrap*, int, char**) /browser/app/../../ipc/contentproc/plugin-container.cpp:63:30
    #20 0x517c32 in main /browser/app/nsBrowserApp.cpp:280:18
    #21 0x7f05591c91c0 in __libc_start_main /build/glibc-itYbWN/glibc-2.26/csu/../csu/libc-start.c:308
    #22 0x4207a9 in _start (firefox+0x4207a9)

Comment 3

[Chris H-C :chutten]

Ah. Not a dupe, then. Needs a `if (start > end) { Accumulate(0); return; }` in AccumulateTimeDelta similar to the additions from bug 1431868

Comment 4

[Chris H-C :chutten]

Set up as mentored.

Comment 5

[Chris H-C :chutten]

To help Mozilla out with this bug, here's the steps:

0) Comment here on the bug that you want to volunteer to help. I (or someone else) will assign it to you.
1) Download and build the Firefox source code: https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Build_Instructions/Simple_Firefox_build
- If you have any problems, please ask on IRC (https://wiki.mozilla.org/Irc) in the #introduction channel. They're there to help you get started.
- You can also read the Developer Guide, which has answers to most development questions: https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Introduction
2) Start working on this bug. We have to deal with start being greater than end in AccumulateTimeDelta similar to how the fix for bug 1431868 dealt with that situation in AutoTimer.
- If you have any problems with this bug, please comment on this bug and set the needinfo flag for me. Also, you can find me and my teammates on the #telemetry channel on IRC (https://wiki.mozilla.org/Irc) most hours of most days.
3) Build your change with `mach build` and test your change with `mach test toolkit/components/telemetry/tests/`. Also check your changes for adherence to our style guidelines by using `mach lint`
4) Submit the patch (including an automated test. This will likely be a GTest (see the toolkit/components/telemetry/tests/gtest/ folder for our existing gtests)) for review. Mark me as a reviewer so I'll get an email to come look at your code.
- Here's the guide: https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/How_to_Submit_a_Patch
5) After a series of reviews and changes to your patch, I'll mark it for checkin or push it to autoland. Your code will soon be shipping to Firefox users worldwide!
6) ...now you get to think about what kind of bug you'd like to work on next. Let me know what you're interested in and I can help you find your next contribution.

Comment 6

[Dhi Aurrahman]

Hi Chris, could you please let me work on this bug? Thanks!

Comment 7

[Chris H-C :chutten]

Certainly! Let me know if you have any questions.

Comment 8

[Dhi Aurrahman]

Hi Chris, I'm pretty sure this is cured by https://reviewboard-hg.mozilla.org/gecko/raw-rev/c0ac844aa10f do you want me to add tests on it? Will a fabricated test e.g. `AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT, TimeStamp::Now()+TimeDuration(1), TimeStamp::Now())` do?

Comment 9

[Dhi Aurrahman]

Attachment: Add test cases for AccumulateTimeDelta

Comment 10

[Chris H-C :chutten]

Comment on attachment 8955748 [details] [diff] [review]
Add test cases for AccumulateTimeDelta

Review of attachment 8955748 [details] [diff] [review]:
-----------------------------------------------------------------

Thank you for your investigation and these test cases!

You are correct, it seems as though bug 1432791 fixed more than just the microsecond resolution autotimer. But tests are a welcome addition, as bug 1432791 didn't introduce test coverage for the new code.

I have a couple of small things to say about it. Mostly it's down to "we can't trust C++, so we have to do a little extra work", and then we'll be able to get this into the tree.

I didn't mark _all_ of the AccumulateTimeDelta calls, but all of them should have a defined "start" and "end" parameter to avoid issues.

::: toolkit/components/telemetry/tests/gtest/TestHistograms.cpp
@@ +736,5 @@
> +
> +  Telemetry::AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT,
> +                                 TimeStamp::Now() - TimeDuration::FromMilliseconds(50));
> +
> +  // Accumulation of time delta in the provided key within the histogram with

I think this comment was copied from the keyed test case. It can be omitted.

@@ +738,5 @@
> +                                 TimeStamp::Now() - TimeDuration::FromMilliseconds(50));
> +
> +  // Accumulation of time delta in the provided key within the histogram with
> +  // end > start timestamp gives zero contribution.
> +  Telemetry::AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT, TimeStamp::Now());

The order of evaluation of function arguments in c++ is undefined, so it's entirely possible that in slow, weird cases this may succeed at recording small numbers. 

If you specifically want to test end == start, create two timestamp locals and set them to the exact same timestamp. That way we can be certain.

@@ +742,5 @@
> +  Telemetry::AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT, TimeStamp::Now());
> +
> +  // Accumulation of time delta in the provided key within the histogram with
> +  // end > start timestamp gives zero contribution.
> +  Telemetry::AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT,

Same sort of problem here. Specify both end and start in the function call, with pre-evaluated parameters, and that'll sort it even in the edge cases.

Comment 11

[Dhi Aurrahman]

Attachment: Add test cases for AccumulateTimeDelta

Comment 12

[Dhi Aurrahman]

Attachment: Add test cases for AccumulateTimeDelta

Comment 13

[Chris H-C :chutten]

Comment on attachment 8956108 [details] [diff] [review]
Add test cases for AccumulateTimeDelta

Review of attachment 8956108 [details] [diff] [review]:
-----------------------------------------------------------------

Thank you for the changes! I think these are sufficiently compiler-proof now.

I do have a few comments about the choices of parameters from a readability standpoint. I think ordering these in a certain way will make it easier for future contributors to understand what the test is testing, and what parts of it are important.

I commented in the non-keyed case, but the comments apply to the similar calls in the keyed test case as well.

::: toolkit/components/telemetry/tests/gtest/TestHistograms.cpp
@@ +734,5 @@
> +  GetAndClearHistogram(cx.GetJSContext(), mTelemetry, NS_LITERAL_CSTRING("TELEMETRY_TEST_COUNT"),
> +                       false);
> +
> +  // Accumulate in the histogram
> +  Telemetry::AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT, end - delta, start);

Having start and end backwards like this makes it difficult to understand what is going on. I recommend `start - delta, start` to show that the only important thing is that it records a "delta" duration.

@@ +736,5 @@
> +
> +  // Accumulate in the histogram
> +  Telemetry::AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT, end - delta, start);
> +
> +  Telemetry::AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT, end - delta, start);

Here as well.

@@ +738,5 @@
> +  Telemetry::AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT, end - delta, start);
> +
> +  Telemetry::AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT, end - delta, start);
> +
> +  // end > start timestamp gives zero contribution

end isn't > start in this accumulation. end _is_ start.

@@ +739,5 @@
> +
> +  Telemetry::AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT, end - delta, start);
> +
> +  // end > start timestamp gives zero contribution
> +  Telemetry::AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT, end, start);

This can be `start, start`

@@ +742,5 @@
> +  // end > start timestamp gives zero contribution
> +  Telemetry::AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT, end, start);
> +
> +  // end + delta > start timestamp gives zero contribution.
> +  Telemetry::AccumulateTimeDelta(Telemetry::TELEMETRY_TEST_COUNT, end + delta, start);

`start + delta, start` would be a clearer way to show this.

Comment 14

[Dhi Aurrahman]

Attachment: Add test cases for AccumulateTimeDelta

Comment 15

[Chris H-C :chutten]

Comment on attachment 8956123 [details] [diff] [review]
Add test cases for AccumulateTimeDelta

Review of attachment 8956123 [details] [diff] [review]:
-----------------------------------------------------------------

Great! Thank you for these test cases. I'll go ahead and mark these for inclusion in the tree.

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/aed9a827a1b9
Add test cases for AccumulateTimeDelta. r=chutten

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e372427420a8
Add test cases for AccumulateTimeDelta. r=chutten

Comment 18

[Dhi Aurrahman]

(In reply to Chris H-C :chutten from comment #15)
> Comment on attachment 8956123 [details] [diff] [review]
> Add test cases for AccumulateTimeDelta
> 
> Review of attachment 8956123 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Great! Thank you for these test cases. I'll go ahead and mark these for
> inclusion in the tree.

Thanks for your guidance Chris!

Comment 19

[Cosmin Sabou [:CosminS]]

Backed out for build bustages at tests/gtest/TestHistograms.cp

Treehder push with failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&noautoclassify&fromchange=aed9a827a1b9b91fe73caacb1bb70f8237c6999c&tochange=fd038d63f99f3b9bc855e8aab4eb0a0c60353149&selectedJob=166082451

Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=166082451&repo=mozilla-inbound&lineNumber=20618

Backout link: https://hg.mozilla.org/integration/mozilla-inbound/rev/fd038d63f99f3b9bc855e8aab4eb0a0c60353149

Comment 20

[Dhi Aurrahman]

(In reply to Cosmin Sabou [:cosmin_s] from comment #19)
> Backed out for build bustages at tests/gtest/TestHistograms.cp
> 
> Treehder push with failures:
> https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-
> resultStatus=testfailed&filter-resultStatus=busted&filter-
> resultStatus=exception&noautoclassify&fromchange=aed9a827a1b9b91fe73caacb1bb7
> 0f8237c6999c&tochange=fd038d63f99f3b9bc855e8aab4eb0a0c60353149&selectedJob=16
> 6082451
> 
> Failure log:
> https://treeherder.mozilla.org/logviewer.html#?job_id=166082451&repo=mozilla-
> inbound&lineNumber=20618
> 
> Backout link:
> https://hg.mozilla.org/integration/mozilla-inbound/rev/
> fd038d63f99f3b9bc855e8aab4eb0a0c60353149

Hi Chris, could you help me.

I'm not sure why we have duplicated test for AccumulateTimeDelta ([1] and [2]) and AccumulateKeyedTimeDelta ([3] and [4]). Thanks!

[1] https://hg.mozilla.org/integration/mozilla-inbound/file/e372427420a8/toolkit/components/telemetry/tests/gtest/TestHistograms.cpp#l725
[2] https://hg.mozilla.org/integration/mozilla-inbound/file/e372427420a8/toolkit/components/telemetry/tests/gtest/TestHistograms.cpp#l810
[3] https://hg.mozilla.org/integration/mozilla-inbound/file/e372427420a8/toolkit/components/telemetry/tests/gtest/TestHistograms.cpp#l764
[4] https://hg.mozilla.org/integration/mozilla-inbound/file/e372427420a8/toolkit/components/telemetry/tests/gtest/TestHistograms.cpp#l849

Comment 21

[Chris H-C :chutten]

That -is- a good question. Your patch only adds two tests, but the push has four.

Looking back in the comments, comment 16 shows it being pushed and comment 17 shows it being pushed a second time.

That's really interesting. I think we can just mark this for checkin and assume it'll be pushed only a single time this time :)

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/1ac4c25a8382
Add test cases for AccumulateTimeDelta r=chutten

Comment 23

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/1ac4c25a8382

Comment 24

[Dhi Aurrahman]

(In reply to Chris H-C :chutten from comment #21)
> That -is- a good question. Your patch only adds two tests, but the push has
> four.
> 
> Looking back in the comments, comment 16 shows it being pushed and comment
> 17 shows it being pushed a second time.
> 
> That's really interesting. I think we can just mark this for checkin and
> assume it'll be pushed only a single time this time :)

It seems it is resolved now. :tada: