Open Bug 1440161 Opened 3 years ago Updated 1 year ago

Intermittent CRITICAL - Test harness output was not a valid structured log message - code 400

Categories

(Testing :: web-platform-tests, defect)

defect
Not set
normal

Tracking

(Not tracked)

REOPENED

People

(Reporter: nataliaCs, Unassigned)

References

Details

(Keywords: intermittent-failure)

Noticed this failure on this push 
https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=c9dc10752a478322dc99201b0b215c7fd1d7a44b&selectedJob=163522397 
The log was not parsed, and going through the raw logs https://public-artifacts.taskcluster.net/FsSDmRTgSpuUaDEHRu-OCg/0/public/logs/live_backing.log noticed the following criticals

19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:39:32] code 400, message Bad request syntax ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03~\t\x7f\x1a\xb0\xd5\x99\xbf\xd5\x00\x08}\x88\t\xe7=\xc0\xffD\x90\x08\x9c\xd6\xbb9g\x11\xc1\xfe^\xa3S \xd8\xe1`z*\xff\x98W,,4\xb19B)f&%i\xf9\x01\x9ds.g\xce\xdf\xa0\x9e\xfc\x9f\xf2\x00\x1c\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\x13\xc0\x14\x00/\x005\x00')
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:39:32] "���~	�ՙ���}�	�=��D��ֻ9g��^�S ��`z*��W,,4�9B)f&%i��s.g�ߠ�����
19:43:19 CRITICAL - �+�/̨̩�,�0���/�5�" 400 -

19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - {"source": "web-platform-tests", "thread": "Thread-TestrunnerManager-1", "time": 1519242199716, "action": "log", "message": "Got command: 'test_ended'", "level": "DEBUG", "pid": 5776}
19:43:19     INFO - ......
19:43:19     INFO - TEST-OK | /webrtc/RTCPeerConnection-peerIdentity.html | took 409ms
Duplicate of this bug: 1441200
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → DUPLICATE
Duplicate of bug: 1224931
I don't think this is a duplicate of that bug.

The log output reports that an invalid structured log entry was made - which is something that should be fixed in addition to treeherder's ability to show an error summary for such logs.
Status: RESOLVED → REOPENED
Resolution: DUPLICATE → ---
Flags: needinfo?(james)
If bug 1441200 is a dupe of this one and also bug 1224931, doesn't mean that all three are the same?
Flags: needinfo?(emorley)
There are two bugs:
1) sometimes for whatever reason the structured log entries are invalid (something wrong with the test/the harness/...
2) those invalid logs trigger a treeherder/Django/Mysql escaping bug with the bug suggestions feature (even though logs should be valid, Treeherder's log parser shouldn't choke on certain combinations of characters)

#1 is this bug.
#2 is bug 1224931.

Bug 1441200 is a dupe of the combination of the two. I don't mind which its duped to, but we still need two open bugs for this.
Flags: needinfo?(emorley)
Ok. Thanks for the clarification.
Filing "Test harness output was not a valid structured log message" as an intermittent failure is not useful. That's generic boilerplate that's whenever some unstructured logging happens. But the actual error is always in the following line. 

It looks like there's some intermittent here in wpt where sometimes we send a tls-encrypted request to a non-tls server and bad stuff happens. I'm not sure why that's going on, but it's certainly not the same issue as all the failures in reftests and other testsuites that it has been classified with.
Flags: needinfo?(james)
Here is an example of how a test goes:

19:43:19     INFO - TEST-START | /webrtc/RTCPeerConnection-peerIdentity.html
19:43:19     INFO - Clearing pref media.navigator.permission.disabled
19:43:19     INFO - Clearing pref media.navigator.streams.fake
19:43:19     INFO - Setting pref media.navigator.permission.disabled (true)
19:43:19     INFO - Setting pref media.navigator.streams.fake (true)
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:39:32] code 400, message Bad request syntax ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03~\t\x7f\x1a\xb0\xd5\x99\xbf\xd5\x00\x08}\x88\t\xe7=\xc0\xffD\x90\x08\x9c\xd6\xbb9g\x11\xc1\xfe^\xa3S \xd8\xe1`z*\xff\x98W,,4\xb19B)f&%i\xf9\x01\x9ds.g\xce\xdf\xa0\x9e\xfc\x9f\xf2\x00\x1c\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\x13\xc0\x14\x00/\x005\x00')
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:39:32] "���~	�ՙ���}�	�=��D��ֻ9g��^�S ��`z*��W,,4�9B)f&%i��s.g�ߠ�����
19:43:19 CRITICAL - �+�/̨̩�,�0���/�5�" 400 -
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:39:54] code 400, message Bad request syntax ("\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03\r/r\x19'\rD\x9f\xef\x9d%\x06\xd3\xc4;\xe7\xcck\xa2U\x84\x16\x05`\xda\t`9\xf2\xc8\xd4\x8c g\x96\x08!HU\x998'\xc4\xe9\xef\xc2\x86\xc1\xa8t\xdf\x81\xd6Zpu\xd5\xaf\xb8\x18QC\x0b\xdfk\x00\x1c\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\x13\xc0\x14\x00/\x005\x00")
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:39:54] "���
19:43:19 CRITICAL - /r'
19:43:19 CRITICAL - D��%��;��k�U�`�	`9��Ԍ g�!HU�8'�����t߁�Zpuկ�QC
19:43:19 CRITICAL - �k�
19:43:19 CRITICAL - �+�/̨̩�,�0���/�5�" 400 -
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:39:55] code 400, message Bad HTTP/0.9 request type ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03\xea\xbcP&\xf1\xbdI[\xd8=\xb5\xc5\xad\xfc%\xee\\]\xc2\xf9T\xfet\xc3\xc5\xbf\xf7Q[!\xbc\xaa')
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:39:55] "����P&�I[�=�ŭ�%�\]��T�t�ſ�Q[!�� D�Pvg$mȠݒW�%o̎���MՔ��7X��
19:43:19 CRITICAL - �+�/̨̩�,�0���/�5�" 400 -
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:43:19] code 400, message Bad request version ('\xe9\xd7\xaeBgK\xbd,Q#Z\xb5r~~I\x89\x15Ob\xae-\x11W<\xdf3p*\xedT?\x00\x1c\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\x13\xc0\x14\x00/\x005\x00')
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:43:19] "�����ה%�ro%�7[�
19:43:19 CRITICAL - ��@�:L�F�T=��g� �׮BgK�,Q#Z�r~~I�Ob�-W<�3p*�T?�
19:43:19 CRITICAL - �+�/̨̩�,�0���/�5�" 400 -
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:43:19] code 400, message Bad HTTP/0.9 request type ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03\x80:n|\xd6\xf1\x7f\xa9\xdf`\x0e\x81\xbb1x\xfb\xf7zP\x00\xfb4Pg\xe5\xa2b\xd4r\x8f\xe8\xb7')
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:43:19] "����:n|����`��1x��zP��4Pg�b�r�� �����D��,:�v�����" 400 -
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:43:19] code 400, message Bad request syntax ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03`(UB\x80\xcb-I\xa2\xbd\x8d/\xe6\re\xda\x16\xb0@_\x8f)\xc4d\xfb\x8b\xb9#w\xffJ\xf8 \xba\xe27y\xf9\xc4\xf1:\xdc\x99&U;H\xad\x87\x9dM\x8d\xec{\xa4h\xcc\xc7R\x0b.\xa5\xa4\xee\xe6\x00\x1c\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\x13\xc0\x14\x00/\x005\x00')
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:43:19] "���`(UB��-I���/�
19:43:19 CRITICAL - e��@_�)�d���#w�J� ��7y���:ܙ&U;H���M��{�h��R
19:43:19 CRITICAL - .�����
19:43:19 CRITICAL - �+�/̨̩�,�0���/�5�" 400 -
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:43:19] code 400, message Bad request syntax ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03<w\x1c\xb9\x92MO\x03\xa4\x8dB\xee\x85\x1d\x15\xf9\x9e\xd9\x05k-V\xc9\x80\x87\xa5\xb8\xb6!\x02\xaf\xe6 \x96\r)\xe2t\xc1\x10\x13\xb7D\x86t\xf9\x16+$\xc2\x9b\xa0\x0b8\x8eW\xd7^\x03\xbbq\x92\x94C)\x00\x1c\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\x13\xc0\x14\x00/\x005\x00')
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:43:19] "���<w
19:43:19 CRITICAL - ��MO��B�
19:43:19 CRITICAL - ���k-Vɀ����!�� �
19:43:19 CRITICAL - )�t��D�t�+$�
19:43:19 CRITICAL - 8�W�^�q��C)�
19:43:19 CRITICAL - �+�/̨̩�,�0���/�5�" 400 -
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:43:19] code 400, message Bad HTTP/0.9 request type ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03x\xe0\x1b\x96{y\x9f\xae\x82-.k\x93\xfb7\xaf\x8en\x80W\x05\x88\xd7\xa4\x1f\xde\xb2\xc6\x109\x1eq')
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:43:19] "���x��{y���-.k��7��n�W�פ޲�9
19:43:19 CRITICAL - q Ҳ�c�W��&S��z�`�\�38��;Z8�����
19:43:19 CRITICAL - �+�/̨̩�,�0���/�5�" 400 -
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - - [21/Feb/2018 19:43:19] code 400, message Bad request syntax ('\x16\x03\x01\x02\x00\x01\x00\x01\xfc\x03\x03\xd8e\xf0\x9e\x0b\xc7y\xf6\r\xd1\xfe\x90\xc3\xd5\x8d \xaa\xd6X\xd7\\\x959m\xe8XE<\xb0u\xec\xae 2\x97\x87%0\xf7pfsDB\xd2\x95j\xf7\x17\xc1\x97\xef\xc6"\xb7\xf0]E\x9d\xe2\x1e\xceC/\xdd\x00\x1c\x13\x01\x13\x03\x13\x02\xc0+\xc0/\xcc\xa9\xcc\xa8\xc0,\xc00\xc0\x13\xc0\x14\x00/\x005\x00')
19:43:19 CRITICAL - Test harness output was not a valid structured log message: 
19:43:19 CRITICAL - 127.0.0.1 - {"source": "web-platform-tests", "thread": "Thread-TestrunnerManager-1", "time": 1519242199716, "action": "log", "message": "Got command: 'test_ended'", "level": "DEBUG", "pid": 5776}
19:43:19     INFO - ......
19:43:19     INFO - TEST-OK | /webrtc/RTCPeerConnection-peerIdentity.html | took 409ms
Even after getting all these criticals, the test is still shown as successful
You need to log in before you can comment on or make changes to this bug.