RTCP timestamps transmitted from Windows XP have significant clock drift

RESOLVED FIXED in Firefox 65

Status

()

defect
P3
normal
RESOLVED FIXED
5 years ago
8 months ago

People

(Reporter: jib, Assigned: cpeterson)

Tracking

Trunk
mozilla65
x86
Windows XP
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox-esr60 wontfix, firefox62 wontfix, firefox63 wontfix, firefox64 wontfix, firefox65 fixed)

Details

Attachments

(4 attachments)

From tests added in Bug 970686 we're seeing significant clock drift on Windows XP specifically. From https://tbpl.mozilla.org/?tree=Try&rev=73178e26acbd :

758 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/identity/test_setIdentityProviderWithErrors.html | Valid rtcp timestamp 1393964699027.603 <= 1393964698494 (533.60302734375 ms)
797 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/identity/test_setIdentityProviderWithErrors.html | Valid rtcp timestamp 1393964699027.603 <= 1393964698559 (468.60302734375 ms)
821 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/identity/test_setIdentityProviderWithErrors.html | Valid rtcp timestamp 1393964699005.603 <= 1393964698576 (429.60302734375 ms)
860 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/identity/test_setIdentityProviderWithErrors.html | Valid rtcp timestamp 1393964699005.603 <= 1393964698585 (420.60302734375 ms)
897 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/ipc/test_ipc.html | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html |  Valid rtcp timestamp 1393964714550.804 <= 1393964714514 (36.803955078125 ms)
954 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/ipc/test_ipc.html | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html |  Valid rtcp timestamp 1393964714550.804 <= 1393964714500 (50.803955078125 ms)
976 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/ipc/test_ipc.html | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html |  Valid rtcp timestamp 1393964714533.804 <= 1393964714505 (28.803955078125 ms)
1033 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/ipc/test_ipc.html | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html |  Valid rtcp timestamp 1393964714533.804 <= 1393964714508 (25.803955078125 ms)
1061 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/ipc/test_ipc.html | /tests/dom/media/tests/mochitest/test_peerConnection_bug827843.html |  Valid rtcp timestamp 1393964716912.804 <= 1393964716767 (145.803955078125 ms)
1100 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/ipc/test_ipc.html | /tests/dom/media/tests/mochitest/test_peerConnection_bug827843.html |  Valid rtcp timestamp 1393964716912.804 <= 1393964716772 (140.803955078125 ms)
1116 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/ipc/test_ipc.html | /tests/dom/media/tests/mochitest/test_peerConnection_bug827843.html |  Valid rtcp timestamp 1393964716900.804 <= 1393964716775 (125.803955078125 ms)
1155 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/ipc/test_ipc.html | /tests/dom/media/tests/mochitest/test_peerConnection_bug827843.html |  Valid rtcp timestamp 1393964716900.804 <= 1393964716777 (123.803955078125 ms)
1396 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtcp timestamp 1393964744232.603 <= 1393964739934 (4298.60302734375 ms)
1435 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtcp timestamp 1393964744232.603 <= 1393964739994 (4238.60302734375 ms)
1459 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtcp timestamp 1393964744208.603 <= 1393964739990 (4218.60302734375 ms)
1498 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtcp timestamp 1393964744208.603 <= 1393964740001 (4207.60302734375 ms)
1607 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideo.html | Valid rtcp timestamp 1393964745222.603 <= 1393964740873 (4349.60302734375 ms)
1666 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideo.html | Valid rtcp timestamp 1393964745222.603 <= 1393964740917 (4305.60302734375 ms)
1775 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Valid rtcp timestamp 1393964746209.603 <= 1393964741805 (4404.60302734375 ms)
1834 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Valid rtcp timestamp 1393964746209.603 <= 1393964741869 (4340.60302734375 ms)
1943 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicVideo.html | Valid rtcp timestamp 1393964747816.603 <= 1393964744190 (3626.60302734375 ms)
1982 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicVideo.html | Valid rtcp timestamp 1393964747816.603 <= 1393964744318 (3498.60302734375 ms)
2006 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicVideo.html | Valid rtcp timestamp 1393964748764.6028 <= 1393964744336 (4428.602783203125 ms)
2045 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicVideo.html | Valid rtcp timestamp 1393964748764.6028 <= 1393964744350 (4414.602783203125 ms)
2166 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_bug827843.html | Valid rtcp timestamp 1393964750936.603 <= 1393964746154 (4782.60302734375 ms)
2205 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_bug827843.html | Valid rtcp timestamp 1393964750936.603 <= 1393964746213 (4723.60302734375 ms)
2229 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_bug827843.html | Valid rtcp timestamp 1393964750904.603 <= 1393964746230 (4674.60302734375 ms)
2268 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_bug827843.html | Valid rtcp timestamp 1393964750904.603 <= 1393964746238 (4666.60302734375 ms)

The <= comparison is against now + 1 second cushion, so the generated rtcp timestamp is more than 5.6 seconds fast! Other runs in the same try show the timestamp up to 6 seconds *behind*:

902 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtcp timestamp 1393965980794.082 >= 1393965982000 (-1205.91796875 ms)
941 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtcp timestamp 1393965980794.082 >= 1393965982000 (-1205.91796875 ms)
965 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtcp timestamp 1393965980765.0818 >= 1393965982265 (-1499.918212890625 ms)
1004 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudio.html | Valid rtcp timestamp 1393965980765.0818 >= 1393965982265 (-1499.918212890625 ms)
1113 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideo.html | Valid rtcp timestamp 1393965981792.082 >= 1393965983011 (-1218.91796875 ms)
1172 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideo.html | Valid rtcp timestamp 1393965981792.082 >= 1393965983011 (-1218.91796875 ms)
1281 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Valid rtcp timestamp 1393965983100.082 >= 1393965984385 (-1284.91796875 ms)
1340 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoCombined.html | Valid rtcp timestamp 1393965983100.082 >= 1393965984385 (-1284.91796875 ms)
1449 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicVideo.html | Valid rtcp timestamp 1393965985156.082 >= 1393965985577 (-420.91796875 ms)
1488 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicVideo.html | Valid rtcp timestamp 1393965985156.082 >= 1393965985577 (-420.91796875 ms)
1512 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicVideo.html | Valid rtcp timestamp 1393965985155.082 >= 1393965985673 (-517.91796875 ms)
1551 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_basicVideo.html | Valid rtcp timestamp 1393965985155.082 >= 1393965985673 (-517.91796875 ms)
1672 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_bug827843.html | Valid rtcp timestamp 1393965987339.082 >= 1393965989264 (-1924.91796875 ms)
1711 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_bug827843.html | Valid rtcp timestamp 1393965987339.082 >= 1393965989264 (-1924.91796875 ms)
1735 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_bug827843.html | Valid rtcp timestamp 1393965987319.082 >= 1393965989343 (-2023.91796875 ms)
1774 INFO TEST-UNEXPECTED-FAIL | /tests/dom/media/tests/mochitest/test_peerConnection_bug827843.html | Valid rtcp timestamp 1393965987319.082 >= 1393965989343 (-2023.91796875 ms)
Return code: 1

Here the >= comparison (the other way) is against pc.timeCreated - 5 second cushion [1], so the generated rtcp timestamp is more than 7 seconds behind.

These are surprisingly large drifts in a short amount of time and happen only on Windows XP. Not sure what is wrong.

If this truly is a Windows XP problem, then part of the problem may be that, as the patch in Bug 978239 shows, we only sync the short-range realtime timer we're using with the lower resolution system clock on first use, and that offset is applied to all subsequent readings. One possible remedy, depending on where the problem lies, may be to sync more often, however, I don't know if syncing during a call has any deleterious effects. If so, some cleverness may be needed to only sync when no calls are in progress.

[1] The tests referenced will probably land with different sized cushions, probably +- 10 s, since their task is not to catch clock drift (that's what this bug is for) but to verify stats.
Depends on: 981256
backlog: --- → parking-lot
Assignee

Comment 2

9 months ago
Re-enable RTCP timestamp test as per review feedback in bug 1336712 comment 28.

Can we resolve RTCP stats bug 1325430? The RTCStats timestamp issue was fixed in 2017:

https://github.com/w3c/webrtc-pc/issues/729

Depends on D6120
Assignee

Updated

9 months ago
Assignee: nobody → cpeterson
Priority: -- → P3
Comment on attachment 9009851 [details]
Bug 979649 - Part 1: Drop webrtc test check for Windows XP. r?jib

Jan-Ivar Bruaroey [:jib] (needinfo? me) has approved the revision.
Attachment #9009851 - Flags: review+
Assignee

Comment 4

9 months ago
Thanks! Marking leave-open until Jesup has time to review the related RTCP timestamp test changes in patch 2, that were requested in bug 1336712 comment 28.
Keywords: leave-open
See Also: → 1336712

Comment 5

9 months ago
Pushed by cpeterson@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a1f769e90937
Part 1: Drop webrtc test check for Windows XP. r=jib

Comment 7

9 months ago
Pushed by cpeterson@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/6777dd18a3d8
Part 2: Re-enable RTCP timestamp test. r=jesup
Comment on attachment 9009852 [details]
Bug 979649 - Part 2: Re-enable RTCP timestamp test. r?jesup

Randell Jesup [:jesup] has approved the revision.
Attachment #9009852 - Flags: review+
Assignee

Updated

9 months ago
backlog: parking-lot → ---
Keywords: leave-open
See Also: → 1325430

Comment 9

9 months ago
Backout by aciure@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/bd02cc115cb6
Backed out 1 changesets for rtcp timestamp failures CLOSED TREE
Assignee

Comment 11

9 months ago
The test failures:

TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/identity/test_peerConnection_peerIdentity.html | Valid rtcp timestamp 13051283 >= 1538122123952 (-1538109072669 ms) 
checkStats@dom/media/tests/mochitest/pc.js:1793:11
PC_LOCAL_CHECK_STATS/<@dom/media/tests/mochitest/templates.js:383:7
promise callback*PC_LOCAL_CHECK_STATS@dom/media/tests/mochitest/templates.js:382:36
execute/</<@dom/media/tests/mochitest/head.js:850:31
promise callback*execute/<@dom/media/tests/mochitest/head.js:848:14
execute@dom/media/tests/mochitest/head.js:843:12
PeerConnectionTest.prototype.run@dom/media/tests/mochitest/pc.js:486:10
identityPcTest@dom/media/tests/mochitest/identity/identityPcTest.js:52:3
runNetworkTest/<@dom/media/tests/mochitest/pc.js:2207:13
async*runTestWhenReady/<@dom/media/tests/mochitest/head.js:471:41
promise callback*runTestWhenReady@dom/media/tests/mochitest/head.js:471:10
runNetworkTest@dom/media/tests/mochitest/pc.js:2189:9
async*@dom/media/tests/mochitest/identity/test_peerConnection_peerIdentity.html:17:1

TEST-UNEXPECTED-FAIL | dom/media/tests/mochitest/test_peerConnection_addDataChannel.html | Valid rtcp timestamp 1954864 >= 1538121678442 (-1538119723578 ms) 
checkStats@dom/media/tests/mochitest/pc.js:1793:11
PC_LOCAL_CHECK_STATS/<@dom/media/tests/mochitest/templates.js:383:7
promise callback*PC_LOCAL_CHECK_STATS@dom/media/tests/mochitest/templates.js:382:36
execute/</<@dom/media/tests/mochitest/head.js:850:31
promise callback*execute/<@dom/media/tests/mochitest/head.js:848:14
execute@dom/media/tests/mochitest/head.js:843:12
PeerConnectionTest.prototype.run@dom/media/tests/mochitest/pc.js:486:10
@dom/media/tests/mochitest/test_peerConnection_addDataChannel.html:28:5
runNetworkTest/<@dom/media/tests/mochitest/pc.js:2207:13
async*runTestWhenReady/<@dom/media/tests/mochitest/head.js:471:41
promise callback*runTestWhenReady@dom/media/tests/mochitest/head.js:471:10
runNetworkTest@dom/media/tests/mochitest/pc.js:2189:9
async*@dom/media/tests/mochitest/test_peerConnection_addDataChannel.html:15:3
Assignee

Comment 12

9 months ago
Jan-Ivar, Jesup suggested in bug 1336712 comment 28 that these RTCP stat tests be reenabled. However, the stat test [1] fails for outbound_rtcp_audio_0:

> INFO Checking stats for outbound_rtcp_audio_0 : [object Object]
> FAIL Valid rtcp timestamp 55398065 >= 1538273872340 (-1538218474275 ms)
                            ^^^^^^^^

While it passes for inbound_rtp_audio_1:

> INFO Checking stats for inbound_rtp_audio_1 : [object Object]
> PASS Valid rtp timestamp 1538273873956 >= 1538273872340 (1616 ms)
> PASS Valid rtp timestamp 1538273873956 <= 1538273873966 (-10 ms)
                            ^^^^^^^^^^^^

It looks like outbound_rtcp_audio_0 and inbound_rtp_audio_1 are using a different clock epochs. The sender timestamp uses converted NTP time [3] while the receiver timestamp is set [4] from a RealTimeClock that has an arbitrary epoch (not necessarily the Unix epoch).

You mentioned spec changes to RTCStats.timestamp epoch in bug 1343691 comment 5. What is the expected behavior? Is this test valid?

[1] https://searchfox.org/mozilla-central/rev/819cd31a93fd50b7167979607371878c4d6f18e8/dom/media/tests/mochitest/pc.js#1794-1797
[2] https://searchfox.org/mozilla-central/rev/819cd31a93fd50b7167979607371878c4d6f18e8/media/webrtc/signaling/src/peerconnection/PeerConnectionImpl.cpp#3012,3019
[3] https://searchfox.org/mozilla-central/rev/819cd31a93fd50b7167979607371878c4d6f18e8/media/webrtc/signaling/src/media-conduit/AudioConduit.cpp#232,247-248
[4] https://searchfox.org/mozilla-central/rev/819cd31a93fd50b7167979607371878c4d6f18e8/media/webrtc/trunk/webrtc/modules/rtp_rtcp/source/rtcp_receiver.cc#1036,1038
Flags: needinfo?(jib)
Blocks: 1495446
I believe the test is valid. Looks like a real bug. I've filed bug 1495446. Thanks for finding it!
Flags: needinfo?(jib)
Assignee

Comment 14

8 months ago
The Windows clock drift allowance was originally added for Windows XP (in bug 979649). I removed it in https://hg.mozilla.org/mozilla-central/rev/a1f769e90937 but it appears Windows 7 has the same clock drift problem that XP had.
Assignee

Comment 15

8 months ago
One of the commented-out test cases is failing (bug 1495446), so temporarily log an info() statement until bug 1495446 is fixed.

Depends on D9354

Comment 16

8 months ago
Pushed by cpeterson@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/47a7b32e5737
Part 3: Restore Windows clock drift in RTCP timestamp test. r=jib
https://hg.mozilla.org/integration/mozilla-inbound/rev/f4c2c10af632
Part 4: Re-enable RTCP timestamp test. r=jib

Comment 17

8 months ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/47a7b32e5737
https://hg.mozilla.org/mozilla-central/rev/f4c2c10af632
Status: NEW → RESOLVED
Closed: 8 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla65
Seems best to let this change ride with 65 Nightly, but of course, please request uplift if you disagree.
You need to log in before you can comment on or make changes to this bug.