Closed Bug 1644165 Opened 4 years ago Closed 4 years ago

Intermittent 'message'].startswith('TEST-UNEXPECTED'))):

Categories

(Testing :: Mochitest, defect, P5)

Product:
Testing
Component:
Mochitest
Type:
defect

Tracking

(firefox79 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla79
Tracking Flags:
Tracking Status
firefox79 --- fixed

People

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

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Bug 1644165 - [mochitest] Guard against missing 'message' in 'log' messages; r=
47 bytes, text/x-phabricator-request
Details | Review

Filed by: archaeopteryx [at] coole-files.de
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=305477319&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/b34QaDKrTPureJZRCmhSMA/runs/0/artifacts/public/logs/live_backing.log

[task 2020-06-08T14:43:14.274Z] 14:43:14 INFO - GECKO(1801) | [Child 1802: Socket Thread]: D/mtransport Trickle candidate is redundant for stream 'PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_replaceVideoThenRen transport-id=transport_0' because it is completed: candidate:1 1 TCP 2105524479 10.49.56.29 9 typ host tcptype active
[task 2020-06-08T14:43:14.289Z] 14:43:14 INFO - GECKO(1801) | (ice/ERR) ICE(PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_replaceVideoThenRen): peer (PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_replaceVideoThenRen:default), stream(PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_replaceVideoThenRen transport-id=transport_0 - 81c464d1:fb8618ee6c5d8ac6c0ba8b4afa39b71b) tried to trickle ICE in inappropriate state 4
[task 2020-06-08T14:43:14.289Z] 14:43:14 INFO - GECKO(1801) | [Child 1802: Socket Thread]: D/mtransport Trickle candidate is redundant for stream 'PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_replaceVideoThenRen transport-id=transport_0' because it is completed: candidate:0 2 UDP 2122252542 10.49.56.29 64632 typ host
[task 2020-06-08T14:43:14.289Z] 14:43:14 INFO - GECKO(1801) | (ice/ERR) ICE(PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/m
[task 2020-06-08T14:43:14.289Z] 14:43:14 INFO - Exception in thread ProcessReader:
[task 2020-06-08T14:43:14.289Z] 14:43:14 INFO - Traceback (most recent call last):
[task 2020-06-08T14:43:14.289Z] 14:43:14 INFO - File "/usr/local/Cellar/python@2/2.7.16/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 801, in __bootstrap_inner
[task 2020-06-08T14:43:14.289Z] 14:43:14 INFO - self.run()
[task 2020-06-08T14:43:14.289Z] 14:43:14 INFO - File "/usr/local/Cellar/python@2/2.7.16/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.py", line 754, in run
[task 2020-06-08T14:43:14.289Z] 14:43:14 INFO - self.__target(*self.__args, **self.__kwargs)
[task 2020-06-08T14:43:14.289Z] 14:43:14 INFO - File "/Users/cltbld/tasks/task_1591626891/build/venv/lib/python2.7/site-packages/mozprocess/processhandler.py", line 1116, in _read
[task 2020-06-08T14:43:14.289Z] 14:43:14 INFO - callback(line.rstrip())
[task 2020-06-08T14:43:14.289Z] 14:43:14 INFO - File "/Users/cltbld/tasks/task_1591626891/build/venv/lib/python2.7/site-packages/mozprocess/processhandler.py", line 1026, in call
[task 2020-06-08T14:43:14.290Z] 14:43:14 INFO - e(*args, **kwargs)
[task 2020-06-08T14:43:14.290Z] 14:43:14 INFO - File "/Users/cltbld/tasks/task_1591626891/build/tests/mochitest/runtests.py", line 3083, in processOutputLine
[task 2020-06-08T14:43:14.290Z] 14:43:14 INFO - self.harness.message_logger.process_message(message)
[task 2020-06-08T14:43:14.290Z] 14:43:14 INFO - File "/Users/cltbld/tasks/task_1591626891/build/tests/mochitest/runtests.py", line 278, in process_message
[task 2020-06-08T14:43:14.290Z] 14:43:14 ERROR - 'message'].startswith('TEST-UNEXPECTED'))):
[task 2020-06-08T14:43:14.290Z] 14:43:14 INFO - KeyError: 'message'

From the raw log:
{"thread": "ProcessReader", "process": "GECKO(1801)", "pid": 1674, "source": "mochitest", "time": 1591627394269, "action": "process_output", "data": "(ice/ERR) ICE(PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_replaceVideoThenRen): peer (PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_replaceVideoThenRen:default), stream(PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_replaceVideoThenRen transport-id=transport_0 - 81c464d1:fb8618ee6c5d8ac6c0ba8b4afa39"}
{"thread": "ProcessReader", "process": "GECKO(1801)", "pid": 1674, "source": "mochitest", "time": 1591627394269, "action": "process_output", "data": "b71b) tried to trickle ICE in inappropriate state 4"}
{"thread": "ProcessReader", "process": "GECKO(1801)", "pid": 1674, "source": "mochitest", "time": 1591627394269, "action": "process_output", "data": "[Child 1802: Socket Thread]: D/mtransport Trickle candidate is redundant for stream 'PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_replaceVideoThenRen transport-id=transport_0' because it is completed: candidate:1 1 TCP 2105524479 10.49.56.29 9 typ host tcptype active"}
{"thread": "ProcessReader", "process": "GECKO(1801)", "pid": 1674, "source": "mochitest", "time": 1591627394277, "action": "process_output", "data": "(ice/ERR) ICE(PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_replaceVideoThenRen): peer (PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_replaceVideoThenRen:default), stream(PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_replaceVideoThenRen transport-id=transport_0 - 81c464d1:fb8618ee6c5d8ac6c0ba8b4afa39b71b) tried to trickle ICE in inappropriate state 4"}
{"thread": "ProcessReader", "process": "GECKO(1801)", "pid": 1674, "source": "mochitest", "time": 1591627394277, "action": "process_output", "data": "[Child 1802: Socket Thread]: D/mtransport Trickle candidate is redundant for stream 'PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_replaceVideoThenRen transport-id=transport_0' because it is completed: candidate:0 2 UDP 2122252542 10.49.56.29 64632 typ host"}
{"thread": "ProcessReader", "process": "GECKO(1801)", "pid": 1674, "source": "mochitest", "time": 1591627394277, "action": "process_output", "data": "(ice/ERR) ICE(PC:1591627392594400 (id=2147484142 url=https://example.com/tests/dom/m"}
{"source": "mochitest", "process": "Main app process", "thread": "MainThread", "time": 1591627539549, "action": "process_exit", "pid": 1674, "exitcode": 0}
{"source": "mochitest", "thread": "MainThread", "time": 1591627539549, "action": "log", "message": "runtests.py | Application ran for: 0:06:07.592762", "level": "INFO", "pid": 1674}
{"source": "mochitest", "thread": "MainThread", "time": 1591627539549, "action": "log", "message": "zombiecheck | Reading PID log: /var/folders/10/6zl_rjhj0x17q080_d33bvt0000017/T/tmp1UeNqFpidlog", "level": "INFO", "pid": 1674}

Assignee: nobody → gbrown

This is just like bug 1643400, just downstream from that fix.

See Also: → 1643400

(In reply to Geoff Brown [:gbrown] from comment #1)

This is just like bug 1643400, just downstream from that fix.

Both failures are in mochitest-media on osx, but in different variants and during different tests. Both have media "ICE" logging just before the failure, but it is not clear that the last logged line is the line that causes the python exception.

I see no "log" actions in the raw log that do not contain "message", the condition reported here.

...no, even after many retries, no sign of this condition in the try push.

Avoids infrequent intermittent failure.

Pushed by gbrown@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/382190d64932
[mochitest] Guard against missing 'message' in 'log' messages; r=bc

https://hg.mozilla.org/mozilla-central/rev/382190d64932

Status: NEW → RESOLVED
Closed: 4 years ago
status-firefox79: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla79
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: