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

Status: REOPENED

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

Description

[Natalia Csoregi [:nataliaCs]]

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

Comment 1

[Intermittent Failures Robot]

11 failures in 675 pushes (0.016 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 6
* mozilla-central: 5

Platform breakdown:
* windows10-64: 10
* windows10-64-nightly: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1440161&startday=2018-02-19&endday=2018-02-25&tree=all

Comment 4

[Ed Morley [:emorley]]

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.

Comment 5

[Cosmin Sabou [:CosminS]]

If bug 1441200 is a dupe of this one and also bug 1224931, doesn't mean that all three are the same?

Comment 6

[Ed Morley [: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.

Comment 7

[Cosmin Sabou [:CosminS]]

Ok. Thanks for the clarification.

Comment 8

[Intermittent Failures Robot]

17 failures in 831 pushes (0.02 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 8
* mozilla-inbound: 7
* mozilla-central: 2

Platform breakdown:
* windows10-64: 15
* windows7-32: 1
* linux64-qr: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1440161&startday=2018-02-26&endday=2018-03-04&tree=all

Comment 9

[James Graham [:jgraham]]

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.

Comment 10

[Natalia Csoregi [:nataliaCs]]

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

Comment 11

[Intermittent Failures Robot]

1 failures in 2808 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1440161&startday=2018-11-26&endday=2018-12-02&tree=all

Comment 12

[Intermittent Failures Robot]

1 failures in 5197 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform breakdown:

• windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1440161&startday=2019-06-03&endday=2019-06-09&tree=all

Comment 13

[Intermittent Failures Robot]

1 failures in 4040 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1440161&startday=2020-11-09&endday=2020-11-15&tree=all

Comment 15

[Intermittent Failures Robot]

1 failures in 4322 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-ccov: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1440161&startday=2021-02-08&endday=2021-02-14&tree=all

Comment 16

[Intermittent Failures Robot]

1 failures in 4622 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1440161&startday=2021-03-08&endday=2021-03-14&tree=all

Comment 17

[Intermittent Failures Robot]

1 failures in 4257 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1440161&startday=2021-03-15&endday=2021-03-21&tree=all

Comment 18

[Intermittent Failures Robot]

1 failures in 3967 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows7-32: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1440161&startday=2021-03-22&endday=2021-03-28&tree=all

Comment 19

[Intermittent Failures Robot]

1 failures in 3854 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-asan: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1440161&startday=2021-04-05&endday=2021-04-11&tree=all

Comment 20

[Intermittent Failures Robot]

1 failures in 2819 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows10-32-2004-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1440161&startday=2021-11-22&endday=2021-11-28&tree=all

Comment 21

[Intermittent Failures Robot]

3 failures in 3072 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1
• mozilla-central: 1
• try: 1

Platform and build breakdown:

• windows10-64-2004-qr: 1
  • debug: 1
• linux1804-64-asan-qr: 1
  • opt: 1
• linux1804-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1440161&startday=2022-07-04&endday=2022-07-10&tree=all

Comment 22

[Intermittent Failures Robot]

1 failures in 3530 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• linux1804-64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1440161&startday=2023-01-09&endday=2023-01-15&tree=all

Comment 23

[Intermittent Failures Robot]

1 failures in 3752 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-2004-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1440161&startday=2023-02-27&endday=2023-03-05&tree=all