Closed Bug 1558887 Opened 5 years ago Closed 5 years ago

OSX Mojave (10.14) - WebRtcIceConnectTest.TestConsentDelayed | Expected equality of these values:

Categories

(Core :: WebRTC: Networking, defect, P5)

Product:
Core
Component:
WebRTC: Networking
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla70
Tracking Flags:
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- fixed
firefox68 --- wontfix
firefox69 --- fixed
firefox70 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: bwc)

References

Details

(Keywords: regression)

Attachments

(1 file)

Bug 1558887: Reduce this STUN response delay a little, since on some platforms it seems to be too long. r?mjf
47 bytes, text/x-phabricator-request
Details | Review

Filed by: egao [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=251074328&repo=try
Full log: https://queue.taskcluster.net/v1/task/MSgzLG2BQAa3UuzSunBogw/runs/0/artifacts/public/logs/live_backing.log

Context:
02:25:27 INFO - TEST-START | WebRtcIceConnectTest.TestConsentDelayed
02:25:27 INFO - Candidate for stream P1:stream0 initialized: candidate:0 1 UDP 2122252543 10.49.56.31 64803 typ host
02:25:27 INFO - P1 Gathering complete
02:25:27 INFO - P1 ATTRIBUTES:
02:25:27 INFO - Stream P1:stream0
02:25:27 INFO - candidate:0 1 UDP 2122252543 10.49.56.31 64803 typ host
02:25:27 INFO - ice-ufrag:P1-151-ufrag
02:25:27 INFO - ice-pwd:P1-151-pwd
02:25:27 INFO - Candidate for stream P2:stream0 initialized: candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host
02:25:27 INFO - P2 Gathering complete
02:25:27 INFO - P2 ATTRIBUTES:
02:25:27 INFO - Stream P2:stream0
02:25:27 INFO - candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host
02:25:27 INFO - ice-ufrag:P2-152-ufrag
02:25:27 INFO - ice-pwd:P2-152-pwd
02:25:27 INFO - P1 Returning candidate: candidate:0 1 UDP 2122252543 10.49.56.31 64803 typ host
02:25:27 INFO - P2 Adding remote attribute: candidate:0 1 UDP 2122252543 10.49.56.31 64803 typ host
02:25:27 INFO - P2 Adding remote attribute: ice-ufrag:P1-151-ufrag
02:25:27 INFO - P2 Adding remote attribute: ice-pwd:P1-151-pwd
02:25:27 INFO - P2 ICE reached checking
02:25:27 INFO - P2 Returning candidate: candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host
02:25:27 INFO - P1 Adding remote attribute: candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host
02:25:27 INFO - P1 Adding remote attribute: ice-ufrag:P2-152-ufrag
02:25:27 INFO - P1 Adding remote attribute: ice-pwd:P2-152-pwd
02:25:27 INFO - P1 ICE reached checking
02:25:27 INFO - P2 Stream ready for P2:stream0 ct=1
02:25:27 INFO - Begin list of candidate pairs [
02:25:27 INFO - Local --> host 10.49.56.31:57235/udp codeword=Eedq
02:25:27 INFO - Remote --> host 10.49.56.31:64803/udp codeword=PVC0
02:25:27 INFO - state = 4 priority = 9115005270282338815 nominated = 1 selected = 1 codeword = RX5J
02:25:27 INFO - ]
02:25:27 INFO - P2 ICE connected
02:25:27 INFO - P1 Stream ready for P1:stream0 ct=1
02:25:27 INFO - Begin list of candidate pairs [
02:25:27 INFO - Local --> host 10.49.56.31:64803/udp codeword=gAF8
02:25:27 INFO - Remote --> host 10.49.56.31:57235/udp codeword=w7FS
02:25:27 INFO - state = 4 priority = 9115005270282338815 nominated = 1 selected = 1 codeword = KAVn
02:25:27 INFO - ]
02:25:27 INFO - P1 ICE connected
02:25:27 INFO - P1 Active candidates:
02:25:27 INFO - P1 Stream P1:stream0 component 1
02:25:27 INFO - Local --> host 10.49.56.31:64803/udp codeword=gAF8
02:25:27 INFO - Remote --> host 10.49.56.31:57235/udp codeword=w7FS
02:25:27 INFO - P2 Active candidates:
02:25:27 INFO - P2 Stream P2:stream0 component 1
02:25:27 INFO - Local --> host 10.49.56.31:57235/udp codeword=Eedq
02:25:27 INFO - Remote --> host 10.49.56.31:64803/udp codeword=PVC0
02:25:27 INFO - P1: new consent timestamp = 1560219927.131249
02:25:27 INFO - P2: new consent timestamp = 1560219927.130878
02:25:27 INFO - P1: sent 4 bytes
02:25:27 INFO - P2: received 4 bytes
02:25:28 INFO - P2 ICE disconnected
02:25:28 INFO - P1: new consent timestamp = 1560219928.103291
02:25:28 WARNING - TEST-UNEXPECTED-FAIL | WebRtcIceConnectTest.TestConsentDelayed | Expected equality of these values:
02:25:28 INFO - r_timeval_cmp(&timestamp, &consent_timestamp_)
02:25:28 INFO - Which is: 0
02:25:28 INFO - 1 @ /builds/worker/workspace/build/src/media/mtransport/test/ice_unittest.cpp:1272
02:25:28 INFO - insert 'ice' (registry) succeeded: ice
02:25:28 INFO - insert 'ice.pref' (registry) succeeded: ice.pref
02:25:28 INFO - insert 'ice.pref.type' (registry) succeeded: ice.pref.type
02:25:28 INFO - insert 'ice.pref.type.srv_rflx' (UCHAR) succeeded: 0x64
02:25:28 INFO - insert 'ice.pref.type.peer_rflx' (UCHAR) succeeded: 0x6e
02:25:28 INFO - insert 'ice.pref.type.host' (UCHAR) succeeded: 0x7e
02:25:28 INFO - insert 'ice.pref.type.relayed' (UCHAR) succeeded: 0x05
02:25:28 INFO - insert 'ice.pref.type.srv_rflx_tcp' (UCHAR) succeeded: 0x63
02:25:28 INFO - insert 'ice.pref.type.peer_rflx_tcp' (UCHAR) succeeded: 0x6d
02:25:28 INFO - insert 'ice.pref.type.host_tcp' (UCHAR) succeeded: 0x7d
02:25:28 INFO - insert 'ice.pref.type.relayed_tcp' (UCHAR) succeeded: 0x00
02:25:28 INFO - insert 'stun' (registry) succeeded: stun
02:25:28 INFO - insert 'stun.client' (registry) succeeded: stun.client
02:25:28 INFO - insert 'stun.client.maximum_transmits' (UINT4) succeeded: 7
02:25:28 INFO - insert 'ice.trickle_grace_period' (UINT4) succeeded: 5000
02:25:28 INFO - insert 'ice.tcp' (registry) succeeded: ice.tcp
02:25:28 INFO - insert 'ice.tcp.so_sock_count' (INT4) succeeded: 3
02:25:28 INFO - insert 'ice.tcp.listen_backlog' (INT4) succeeded: 10
02:25:28 INFO - insert 'ice.tcp.disable' (char) succeeded: \001
02:25:28 INFO - ICE-CANDIDATE(srflx(IP4:10.49.56.31:64803/UDP|:19305)): Can't use DNS names without a resolver
02:25:28 INFO - ICE(P1)/CAND(srflx(IP4:10.49.56.31:64803/UDP|:19305)): failed to initialize, 1 remaining
02:25:28 INFO - ICE(P1): All candidates initialized
02:25:28 INFO - ICE-CANDIDATE(srflx(IP4:10.49.56.31:57235/UDP|:19305)): Can't use DNS names without a resolver
02:25:28 INFO - ICE(P2)/CAND(srflx(IP4:10.49.56.31:57235/UDP|:19305)): failed to initialize, 1 remaining
02:25:28 INFO - ICE(P2): All candidates initialized
02:25:28 INFO - ICE(P2): peer (P2:default) has no stream matching stream P2:stream0 - P2-152-ufrag:P2-152-pwd
02:25:28 INFO - ICE-PEER(P2:default)/CAND-PAIR(RX5J): setting pair to state FROZEN: RX5J|IP4:10.49.56.31:57235/UDP|IP4:10.49.56.31:64803/UDP(host(IP4:10.49.56.31:57235/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 64803 typ host)
02:25:28 INFO - ICE(P2)/CAND-PAIR(RX5J): Pairing candidate IP4:10.49.56.31:57235/UDP (7e7f00ff):IP4:10.49.56.31:64803/UDP (7e7f00ff) priority=9115005270282338815 (7e7f00fffcfe01ff)
02:25:28 INFO - ICE-PEER(P2:default)/CAND-PAIR(RX5J): setting pair to state WAITING: RX5J|IP4:10.49.56.31:57235/UDP|IP4:10.49.56.31:64803/UDP(host(IP4:10.49.56.31:57235/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 64803 typ host)
02:25:28 INFO - ICE-PEER(P2:default)/ICE-STREAM(P2:stream0 - P2-152-ufrag:P2-152-pwd): Starting check timer for stream.
02:25:28 INFO - ICE-PEER(P2:default)/CAND-PAIR(RX5J): setting pair to state IN_PROGRESS: RX5J|IP4:10.49.56.31:57235/UDP|IP4:10.49.56.31:64803/UDP(host(IP4:10.49.56.31:57235/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 64803 typ host)
02:25:28 INFO - ICE(P2): peer (P2:default) is now checking
02:25:28 INFO - ICE(P2): peer (P2:default) no streams with pre-answer requests
02:25:28 INFO - STUN-SERVER(server(IP4:10.49.56.31:0/UDP)): Falling back to default client, username=: P1-151-ufrag:P2-152-ufrag
02:25:28 INFO - STUN-SERVER(server(IP4:10.49.56.31:0/UDP)): Falling back to default client, username=: P1-151-ufrag:P2-152-ufrag
02:25:28 INFO - ICE(P1): peer (P1:default) has no stream matching stream P1:stream0 - P1-151-ufrag:P1-151-pwd
02:25:28 INFO - ICE-PEER(P1:default)/CAND-PAIR(KAVn): setting pair to state FROZEN: KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host)
02:25:28 INFO - ICE(P1)/CAND-PAIR(KAVn): Pairing candidate IP4:10.49.56.31:64803/UDP (7e7f00ff):IP4:10.49.56.31:57235/UDP (7e7f00ff) priority=9115005270282338815 (7e7f00fffcfe01ff)
02:25:28 INFO - ICE-PEER(P1:default)/CAND-PAIR(KAVn): setting pair to state WAITING: KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host)
02:25:28 INFO - ICE-PEER(P1:default)/ICE-STREAM(P1:stream0 - P1-151-ufrag:P1-151-pwd): Starting check timer for stream.
02:25:28 INFO - ICE-PEER(P1:default)/CAND-PAIR(KAVn): setting pair to state IN_PROGRESS: KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host)
02:25:28 INFO - ICE(P1): peer (P1:default) is now checking
02:25:28 INFO - ICE-PEER(P1:default)/CAND-PAIR(KAVn): triggered check on KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host)
02:25:28 INFO - ICE-PEER(P1:default)/CAND-PAIR(KAVn): setting pair to state FROZEN: KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host)
02:25:28 INFO - ICE(P1)/CAND-PAIR(KAVn): Pairing candidate IP4:10.49.56.31:64803/UDP (7e7f00ff):IP4:10.49.56.31:57235/UDP (7e7f00ff) priority=9115005270282338815 (7e7f00fffcfe01ff)
02:25:28 INFO - CAND-PAIR(KAVn): Adding pair to check list and trigger check queue: KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host)
02:25:28 INFO - ICE-PEER(P1:default)/CAND-PAIR(KAVn): setting pair to state WAITING: KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host)
02:25:28 INFO - ICE-PEER(P1:default)/CAND-PAIR(KAVn): setting pair to state CANCELLED: KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host)
02:25:28 INFO - STUN-CLIENT(RX5J|IP4:10.49.56.31:57235/UDP|IP4:10.49.56.31:64803/UDP(host(IP4:10.49.56.31:57235/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 64803 typ host)): Received response; processing
02:25:28 INFO - ICE-PEER(P2:default)/CAND-PAIR(RX5J): setting pair to state SUCCEEDED: RX5J|IP4:10.49.56.31:57235/UDP|IP4:10.49.56.31:64803/UDP(host(IP4:10.49.56.31:57235/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 64803 typ host)
02:25:28 INFO - ICE-PEER(P2:default)/STREAM(P2:stream0 - P2-152-ufrag:P2-152-pwd)/COMP(1)/CAND-PAIR(RX5J): nominated pair is RX5J|IP4:10.49.56.31:57235/UDP|IP4:10.49.56.31:64803/UDP(host(IP4:10.49.56.31:57235/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 64803 typ host)
02:25:28 INFO - ICE-PEER(P2:default)/STREAM(P2:stream0 - P2-152-ufrag:P2-152-pwd)/COMP(1)/CAND-PAIR(RX5J): cancelling all pairs but RX5J|IP4:10.49.56.31:57235/UDP|IP4:10.49.56.31:64803/UDP(host(IP4:10.49.56.31:57235/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 64803 typ host)
02:25:28 INFO - ICE-PEER(P2:default)/ICE-STREAM(P2:stream0 - P2-152-ufrag:P2-152-pwd): all active components have nominated candidate pairs
02:25:28 INFO - ICE-PEER(P2:default): all checks completed success=1 fail=0
02:25:28 INFO - STUN-CLIENT(KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host)): Received response; processing
02:25:28 INFO - ICE-PEER(P1:default)/CAND-PAIR(KAVn): setting pair to state SUCCEEDED: KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host)
02:25:28 INFO - ICE-PEER(P1:default)/STREAM(P1:stream0 - P1-151-ufrag:P1-151-pwd)/COMP(1)/CAND-PAIR(KAVn): nominated pair is KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host)
02:25:28 INFO - ICE-PEER(P1:default)/STREAM(P1:stream0 - P1-151-ufrag:P1-151-pwd)/COMP(1)/CAND-PAIR(KAVn): cancelling all pairs but KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host)
02:25:28 INFO - ICE-PEER(P1:default)/STREAM(P1:stream0 - P1-151-ufrag:P1-151-pwd)/COMP(1)/CAND-PAIR(KAVn): cancelling FROZEN/WAITING pair KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host) in trigger check queue because CAND-PAIR(KAVn) was nominated.
02:25:28 INFO - ICE-PEER(P1:default)/CAND-PAIR(KAVn): setting pair to state CANCELLED: KAVn|IP4:10.49.56.31:64803/UDP|IP4:10.49.56.31:57235/UDP(host(IP4:10.49.56.31:64803/UDP)|candidate:0 1 UDP 2122252543 10.49.56.31 57235 typ host)
02:25:28 INFO - ICE-PEER(P1:default)/ICE-STREAM(P1:stream0 - P1-151-ufrag:P1-151-pwd): all active components have nominated candidate pairs
02:25:28 INFO - ICE-PEER(P1:default): all checks completed success=1 fail=0
02:25:28 INFO - STUN-CLIENT(consent): Timed out
02:25:28 INFO - ICE(P2)/STREAM(P2:stream0 - P2-152-ufrag:P2-152-pwd)/COMP(1): A single consent refresh request timed out
02:25:28 INFO - ICE(P2)/STREAM(P2:stream0 - P2-152-ufrag:P2-152-pwd)/COMP(1): component disconnected
02:25:28 INFO - ICE(P2): Message does not correspond to any registered stun ctx
02:25:28 INFO - STUN-CLIENT(consent): Received response; processing
02:25:28 INFO - ICE(P1)/STREAM(P1:stream0 - P1-151-ufrag:P1-151-pwd)/COMP(1): Consent refreshed
02:25:28 INFO - P1: sent 4 bytes
02:25:28 INFO - P2: received 4 bytes
02:25:28 INFO - P1 Shutdown
02:25:29 INFO - P2 Shutdown
02:25:30 WARNING - TEST-UNEXPECTED-FAIL | WebRtcIceConnectTest.TestConsentDelayed | test completed (time: 3093ms)
02:25:38 INFO - TEST-START | WebRtcIceConnectTest.TestNetworkOnlineTriggersConsent
02:25:38 INFO - Candidate for stream P1:stream0 initialized: candidate:0 1 UDP 2122252543 10.49.56.31 50207 typ host
02:25:38 INFO - Candidate for stream P1:stream0 initialized: candidate:0 2 UDP 2122252542 10.49.56.31 55512 typ host
02:25:38 INFO - Candidate for stream P1:stream1 initialized: candidate:0 1 UDP 2122252543 10.49.56.31 53956 typ host
02:25:38 INFO - Candidate for stream P1:stream1 initialized: candidate:0 2 UDP 2122252542 10.49.56.31 51039 typ host
02:25:38 INFO - P1 Gathering complete
02:25:38 INFO - P1 ATTRIBUTES:
02:25:38 INFO - Stream P1:stream0
02:25:38 INFO - candidate:0 1 UDP 2122252543 10.49.56.31 50207 typ host
02:25:38 INFO - candidate:0 2 UDP 2122252542 10.49.56.31 55512 typ host
02:25:38 INFO - ice-ufrag:P1-159-ufrag
02:25:38 INFO - ice-pwd:P1-159-pwd
02:25:38 INFO - Stream P1:stream1
02:25:38 INFO - candidate:0 1 UDP 2122252543 10.49.56.31 53956 typ host
02:25:38 INFO - candidate:0 2 UDP 2122252542 10.49.56.31 51039 typ host
02:25:38 INFO - ice-ufrag:P1-161-ufrag
02:25:38 INFO - ice-pwd:P1-161-pwd
02:25:38 INFO - Candidate for stream P2:stream0 initialized: candidate:0 1 UDP 2122252543 10.49.56.31 55313 typ host
02:25:38 INFO - Candidate for stream P2:stream0 initialized: candidate:0 2 UDP 2122252542 10.49.56.31 64682 typ host
02:25:38 INFO - Candidate for stream P2:stream1 initialized: candidate:0 1 UDP 2122252543 10.49.56.31 49856 typ host
02:25:38 INFO - Candidate for stream P2:stream1 initialized: candidate:0 2 UDP 2122252542 10.49.56.31 59370 typ host
02:25:38 INFO - P2 Gathering complete
02:25:38 INFO - P2 ATTRIBUTES:
02:25:38 INFO - Stream P2:stream0
02:25:38 INFO - candidate:0 1 UDP 2122252543 10.49.56.31 55313 typ host
02:25:38 INFO - candidate:0 2 UDP 2122252542 10.49.56.31 64682 typ host
02:25:38 INFO - ice-ufrag:P2-160-ufrag
02:25:38 INFO - ice-pwd:P2-160-pwd
02:25:38 INFO - Stream P2:stream1
02:25:38 INFO - candidate:0 1 UDP 2122252543 10.49.56.31 49856 typ host
02:25:38 INFO - candidate:0 2 UDP 2122252542 10.49.56.31 59370 typ host
02:25:38 INFO - ice-ufrag:P2-162-ufrag
02:25:38 INFO - ice-pwd:P2-162-pwd
02:25:38 INFO - P1 Returning candidate: candidate:0 1 UDP 2122252543 10.49.56.31 50207 typ host
02:25:38 INFO - P1 Returning candidate: candidate:0 2 UDP 2122252542 10.49.56.31 55512 typ host
02:25:38 INFO - P2 Adding remote attribute: candidate:0 1 UDP 2122252543 10.49.56.31 50207 typ host
02:25:38 INFO - P2 Adding remote attribute: candidate:0 2 UDP 2122252542 10.49.56.31 55512 typ host
02:25:38 INFO - P2 Adding remote attribute: ice-ufrag:P1-159-ufrag
02:25:38 INFO - P2 Adding remote attribute: ice-pwd:P1-159-pwd
02:25:38 INFO - P1 Returning candidate: candidate:0 1 UDP 2122252543 10.49.56.31 53956 typ host
02:25:38 INFO - P1 Returning candidate: candidate:0 2 UDP 2122252542 10.49.56.31 51039 typ host
02:25:38 INFO - P2 Adding remote attribute: candidate:0 1 UDP 2122252543 10.49.56.31 53956 typ host
02:25:38 INFO - P2 Adding remote attribute: candidate:0 2 UDP 2122252542 10.49.56.31 51039 typ host
02:25:38 INFO - P2 Adding remote attribute: ice-ufrag:P1-161-ufrag
02:25:38 INFO - P2 Adding remote attribute: ice-pwd:P1-161-pwd
02:25:38 INFO - P2 ICE reached checking
02:25:38 INFO - P2 Returning candidate: candidate:0 1 UDP 2122252543 10.49.56.31 55313 typ host
02:25:38 INFO - P2 Returning candidate: candidate:0 2 UDP 2122252542 10.49.56.31 64682 typ host
02:25:38 INFO - P1 Adding remote attribute: candidate:0 1 UDP 2122252543 10.49.56.31 55313 typ host
02:25:38 INFO - P1 Adding remote attribute: candidate:0 2 UDP 2122252542 10.49.56.31 64682 typ host
02:25:38 INFO - P1 Adding remote attribute: ice-ufrag:P2-160-ufrag
02:25:38 INFO - P1 Adding remote attribute: ice-pwd:P2-160-pwd
02:25:38 INFO - P2 Returning candidate: candidate:0 1 UDP 2122252543 10.49.56.31 49856 typ host
02:25:38 INFO - P2 Returning candidate: candidate:0 2 UDP 2122252542 10.49.56.31 59370 typ host
02:25:38 INFO - P1 Adding remote attribute: candidate:0 1 UDP 2122252543 10.49.56.31 49856 typ host
02:25:38 INFO - P1 Adding remote attribute: candidate:0 2 UDP 2122252542 10.49.56.31 59370 typ host
02:25:38 INFO - P1 Adding remote attribute: ice-ufrag:P2-162-ufrag
02:25:38 INFO - P1 Adding remote attribute: ice-pwd:P2-162-pwd
02:25:38 INFO - P1 ICE reached checking
02:25:38 INFO - P1 Stream ready for P1:stream1 ct=1
02:25:38 INFO - Begin list of candidate pairs [
02:25:38 INFO - Local --> host 10.49.56.31:53956/udp codeword=DYqP
02:25:38 INFO - Remote --> host 10.49.56.31:49856/udp codeword=Di2j
02:25:38 INFO - state = 4 priority = 9115005270282338815 nominated = 1 selected = 1 codeword = sCGZ
02:25:38 INFO - Local --> host 10.49.56.31:51039/udp codeword=s5np
02:25:38 INFO - Remote --> host 10.49.56.31:59370/udp codeword=zrD0
02:25:38 INFO - state = 4 priority = 9115005265987371517 nominated = 1 selected = 1 codeword = 9hLT
02:25:38 INFO - ]
02:25:38 INFO - P1 Stream ready for P1:stream0 ct=2
02:25:38 INFO - Begin list of candidate pairs [
02:25:38 INFO - Local --> host 10.49.56.31:50207/udp codeword=ePKo
02:25:38 INFO - Remote --> host 10.49.56.31:55313/udp codeword=Ne5o
02:25:38 INFO - state = 4 priority = 9115005270282338815 nominated = 1 selected = 1 codeword = G+ag
02:25:38 INFO - Local --> host 10.49.56.31:55512/udp codeword=PF1V
02:25:38 INFO - Remote --> host 10.49.56.31:64682/udp codeword=sEBv
02:25:38 INFO - state = 4 priority = 9115005265987371517 nominated = 1 selected = 1 codeword = 8Jhs
02:25:38 INFO - ]
02:25:38 INFO - P2 Stream ready for P2:stream1 ct=1
02:25:38 INFO - Begin list of candidate pairs [
02:25:38 INFO - Local --> host 10.49.56.31:49856/udp codeword=4XwD
02:25:38 INFO - Remote --> host 10.49.56.31:53956/udp codeword=SVT0
02:25:38 INFO - state = 4 priority = 9115005270282338815 nominated = 1 selected = 1 codeword = MzXh
02:25:38 INFO - Local --> host 10.49.56.31:59370/udp codeword=vq0Z
02:25:38 INFO - Remote --> host 10.49.56.31:51039/udp codeword=gmhZ
02:25:38 INFO - state = 4 priority = 9115005265987371517 nominated = 1 selected = 1 codeword = SUdF
02:25:38 INFO - ]
02:25:38 INFO - P2 Stream ready for P2:stream0 ct=2
02:25:38 INFO - Begin list of candidate pairs [
02:25:38 INFO - Local --> host 10.49.56.31:55313/udp codeword=8LPJ
02:25:38 INFO - Remote --> host 10.49.56.31:50207/udp codeword=x7mL
02:25:38 INFO - state = 4 priority = 9115005270282338815 nominated = 1 selected = 1 codeword = EEtI
02:25:38 INFO - Local --> host 10.49.56.31:64682/udp codeword=lYB1
02:25:38 INFO - Remote --> host 10.49.56.31:55512/udp codeword=Jn47
02:25:38 INFO - state = 4 priority = 9115005265987371517 nominated = 1 selected = 1 codeword = FCDE
02:25:38 INFO - ]
02:25:38 INFO - P1 ICE connected
02:25:38 INFO - P2 ICE connected

:drno - this is a new permafail observed on macosx1014-64-shippable/opt for WebRtcIceConnectTest test (see also: 1558886). Interestingly, this failure is not reproducible on macosx1014-64/debug. Could you please take a look, or pass the ni on to someone that may be able to comment, thank you.

Flags: needinfo?(drno)
Assignee: nobody → docfaraday

It looks like consent is timing out in this test when we didn't intend it to. This is probably because we're speeding up the consent timeout by a factor of 10:

https://searchfox.org/mozilla-central/rev/040aa667f419932adf425d92c7438f03230ad96b/media/mtransport/test/ice_unittest.cpp#1667-1668

And then imposing a 300ms delay on STUN here:

https://searchfox.org/mozilla-central/source/media/mtransport/test/ice_unittest.cpp#3205-3206

Consent is normally supposed to take 5000ms to time out, which we are shortening to 500ms. Maybe a 300ms delay timer is too close for comfort here.

I can shorten the delay, but I wonder if that is going to be sufficient. It seems that these OS 10.14 test machines either aren't firing timers consistently, or threads are hanging periodically. I also wonder whether it really makes sense to have this test; there's always going to be a little bit of delay in consent, so this isn't really testing any code-paths in nICEr that aren't covered by other tests.

Flags: needinfo?(drno)

^ Nils, what do yout think?

Flags: needinfo?(drno)

Strange that they started failing, but were fine for such a long time. My guess would be that points more to an infrastructure change of some sort.

The idea behind the tests is to verify that the consent timeout path works as expected. It's not the end of the world if we loose that test coverage, but I would prefer to test first with increased timeouts if possible. I don't think that we have any other tests covering that consent timeout path.

The other possible alternative would be to run these tests in real time. But I'm sure some folks would hate us for that.

Flags: needinfo?(drno)

Ok, I'll try reducing the delay from 300ms to 200ms.

Hmm. Those 10.14 jobs have been waiting for a really long time. I wonder if they'll time out.

(In reply to Byron Campen [:bwc] from comment #10)

Hmm. Those 10.14 jobs have been waiting for a really long time. I wonder if they'll time out.

Currently macosx1014 hosts are stretched quite thin - the reimaging of existing macosx1010 machines are taking longer than expected.

Also, a fix is currently being merged into m-c via https://bugzilla.mozilla.org/show_bug.cgi?id=1562745. Results from macosx1014/debug may not be trustworthy unless portions of this patch is applied, since debug was inadvertently being run on shippable builds.

Try looks good!

Pushed by bcampen@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/9ee3ac685091
Reduce this STUN response delay a little, since on some platforms it seems to be too long. r=mjf

https://hg.mozilla.org/mozilla-central/rev/9ee3ac685091

Status: NEW → RESOLVED
Closed: 5 years ago
status-firefox70: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla70

Sorry, didn't mean to NI there.

Flags: needinfo?(docfaraday)
Whiteboard: [checkin-needed-beta][checkin-needed-esr68]

https://hg.mozilla.org/releases/mozilla-beta/rev/016e96e8f65f

status-firefox69: affected → fixed
Whiteboard: [checkin-needed-beta][checkin-needed-esr68] → [checkin-needed-esr68]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: