991279 - Intermittent test_sjs_throwing_exceptions.js | Test timed out | test failed (with xpcshell return code: -1)

Status: RESOLVED WORKSFORME

(Core :: Networking, defect)

Description

[Ryan VanderMeulen [:RyanVM]]

https://tbpl.mozilla.org/php/getParsedLog.php?id=37150441&tree=Mozilla-Inbound

Android 2.3 Emulator mozilla-inbound opt test xpcshell-1 on 2014-04-02 09:17:21 PDT for push 1d5baed67b88
slave: tst-linux64-spot-878

10:48:57  WARNING -  TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | Test timed out
10:48:57     INFO -  DeviceManager ERROR | Unable to parse process list (bug 805969)
10:48:57     INFO -  DeviceManager ERROR | Line: HTTPD-INFO | *** Normalized value: 'text/html;charset=utf-8'
10:48:57     INFO -  Full output of process list:
10:48:57     INFO -  HTTPD-INFO | *** Normalized value: 'text/html;charset=utf-8'
10:48:57     INFO -  HTTPD-INFO | *** complete()
10:48:57     INFO -  HTTPD-INFO | *** partiallySent()
10:48:57     INFO -  HTTPD-INFO | *** _startAsyncProcessor()
10:48:57     INFO -  HTTPD-INFO | *** _sendHeaders()
10:48:57     INFO -  HTTPD-INFO | *** Normalized value: 'close'
10:48:57     INFO -  HTTPD-INFO | *** Normalized value: 'httpd.js'
10:48:57     INFO -  HTTPD-INFO | *** Normalized value: 'Wed, 02 Apr 2014 17:47:23 GMT'
10:48:57     INFO -  HTTPD-INFO | *** non-async response, set Content-Length
10:48:57     INFO -  HTTPD-INFO | *** Normalized value: '321'
10:48:57     INFO -  HTTPD-INFO | *** header post-processing completed, sending response head...
10:48:57     INFO -  HTTPD-INFO | *** preamble copying started
10:48:57     INFO -  HTTPD-INFO | *** _waitToReadData
10:48:57     INFO -  HTTPD-INFO | *** _waitForSinkClosure
10:48:57     INFO -  HTTPD-INFO | *** onInputStreamReady
10:48:57     INFO -  HTTPD-INFO | *** input wanted: 172
10:48:57     INFO -  HTTPD-INFO | *** 172 bytes read
10:48:57     INFO -  HTTPD-INFO | *** _waitToWriteData
10:48:57     INFO -  HTTPD-INFO | *** _waitToReadData
10:48:57     INFO -  HTTPD-INFO | *** onOutputStreamReady
10:48:57     INFO -  HTTPD-INFO | *** wrote 172 bytes of data
10:48:57     INFO -  HTTPD-INFO | *** _waitForSinkClosure
10:48:57     INFO -  HTTPD-INFO | *** onInputStreamReady
10:48:57     INFO -  HTTPD-INFO | *** input stream closed
10:48:57     INFO -  HTTPD-INFO | *** _doneReadingSource(0x0)
10:48:57     INFO -  HTTPD-INFO | *** _finishSource(0)
10:48:57     INFO -  HTTPD-INFO | *** _cancelOrDispatchCancelCallback(0)
10:48:57     INFO -  HTTPD-INFO | *** cancel(0)
10:48:57     INFO -  HTTPD-INFO | *** _doneReadingSource(0x0)
10:48:57     INFO -  HTTPD-INFO | *** _finishSource(0)
10:48:57     INFO -  HTTPD-INFO | *** _cancelOrDispatchCancelCallback(0)
10:48:57     INFO -  HTTPD-INFO | *** onStopRequest async callback
10:48:57     INFO -  HTTPD-INFO | *** preamble copying complete [status=0x0]
10:48:57     INFO -  HTTPD-INFO | *** _sendBody
10:48:57     INFO -  HTTPD-INFO | *** starting async copier of body data...
10:48:57     INFO -  HTTPD-INFO | *** onStartRequest
10:48:57     INFO -  HTTPD-INFO | *** _waitToReadData
10:48:57     INFO -  HTTPD-INFO | *** _waitForSinkClosure
10:48:57     INFO -  HTTPD-INFO | *** onInputStreamReady
10:48:57     INFO -  HTTPD-INFO | *** input wanted: 321
10:48:57     INFO -  HTTPD-INFO | *** 321 bytes read
10:48:57     INFO -  HTTPD-INFO | *** _waitToWriteData
10:48:57     INFO -  HTTPD-INFO | *** _waitToReadData
10:48:57     INFO -  HTTPD-INFO | *** onOutputStreamReady
10:48:57     INFO -  HTTPD-INFO | *** wrote 321 bytes of data
10:48:57     INFO -  HTTPD-INFO | *** _waitForSinkClosure
10:48:57     INFO -  HTTPD-INFO | *** onInputStreamReady
10:48:57     INFO -  HTTPD-INFO | *** input stream closed
10:48:57     INFO -  HTTPD-INFO | *** _doneReadingSource(0x0)
10:48:57     INFO -  HTTPD-INFO | *** _finishSource(0)
10:48:57     INFO -  HTTPD-INFO | *** _cancelOrDispatchCancelCallback(0)
10:48:57     INFO -  HTTPD-INFO | *** cancel(0)
10:48:57     INFO -  HTTPD-INFO | *** _doneReadingSource(0x0)
10:48:57     INFO -  HTTPD-INFO | *** _finishSource(0)
10:48:57     INFO -  HTTPD-INFO | *** _cancelOrDispatchCancelCallback(0)
10:48:57     INFO -  
10:48:57     INFO -  {"source_file":"/mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/head_utils.js","test_name":"runHttpTests/listener.onStartRequest","line_number":310,"diagnostic":"[runHttpTests/listener.onStartRequest : 310] true == true\n","action":"test_pass","_time":1396460844541}
10:48:57     INFO -  
10:48:57     INFO -  {"source_file":"test_sjs_throwing_exceptions.js","test_name":"start_thrower","line_number":60,"diagnostic":"[start_thrower : 60] 500 == 500\n","action":"test_pass","_time":1396460844545}
10:48:57     INFO -  
10:48:57     INFO -  {"source_file":"test_sjs_throwing_exceptions.js","test_name":"start_thrower","line_number":61,"diagnostic":"[start_thrower : 61] false == false\n","action":"test_pass","_time":1396460844553}
10:48:57     INFO -  
10:48:57     INFO -  {"_message":"TEST-INFO | (xpcshell/head.js) | test pending (2)\n","action":"test_pending","_time":1396460844598}
10:48:57     INFO -  
10:48:57     INFO -  {"_message":"TEST-INFO | (xpcshell/head.js) | test finished (2)\n","action":"test_finish","_time":1396460844626}
10:48:57     INFO -  HTTPD-INFO | *** onStopRequest async callback
10:48:57     INFO -  HTTPD-INFO | *** onStopRequest [status=0x0]
10:48:57     INFO -  HTTPD-INFO | *** closing connection 187 on port 51397
10:48:57     INFO -  HTTPD-INFO | *** onSocketAccepted(socket=[xpconnect wrapped nsIServerSocket], trans=[xpconnect wrapped (nsISupports, nsISocketTransport, nsITransport, nsIDNSListener)])
10:48:57     INFO -  HTTPD-INFO | >>> new connection on 127.0.0.1:51398
10:48:57     INFO -  HTTPD-INFO | *** opening new connection 188 on port 51398
10:48:57  WARNING -  TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | test failed (with xpcshell return code: -1), see following log:
10:48:57     INFO -  >>>>>>>
10:48:57     INFO -  xpcw: cd /mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test
10:48:57     INFO -  xpcw: xpcshell -r /mnt/sdcard/tests/xpcshell/c/httpd.manifest --greomni /data/local/xpcb/fennec-31.0a1.en-US.android-arm.apk -m -s -e const _HTTPD_JS_PATH = "/mnt/sdcard/tests/xpcshell/c/httpd.js"; -e const _HEAD_JS_PATH = "/mnt/sdcard/tests/xpcshell/head.js"; -e const _TESTING_MODULES_DIR = "/mnt/sdcard/tests/xpcshell/m"; -f /mnt/sdcard/tests/xpcshell/head.js -e const _SERVER_ADDR = "localhost" -e const _HEAD_FILES = ["/mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/head_utils.js"]; -e const _TAIL_FILES = []; -e const _TEST_FILE = ["test_sjs_throwing_exceptions.js"]; -e _execute_test(); quit(0);
10:48:57     INFO -  System JS : WARNING /mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/head_utils.js:67 - octal literals and octal escape sequences are deprecated
10:48:57     INFO -  System JS : WARNING /mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/head_utils.js:67 - octal literals and octal escape sequences are deprecated
10:48:57     INFO -  System JS : WARNING /mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/head_utils.js:67 - octal literals and octal escape sequences are deprecated
10:48:57     INFO -  System JS : WARNING /mnt/sdcard/tests/xpcshell/c/httpd.js:2857 - in strict mode code, functions may be declared only at top level or immediately within another function
10:48:57     INFO -  TEST-INFO | (xpcshell/head.js) | test MAIN run_test pending (1)
10:48:57     INFO -  HTTPD-INFO | *** mapping '/' to the location /mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/data/sjs
10:48:57     INFO -  HTTPD-INFO | *** Normalized value: 'sjs'
10:48:57     INFO -  HTTPD-INFO | >>> listening on port 50914, 25 pending connections
10:48:57     INFO -  TEST-INFO | (xpcshell/head.js) | test pending (2)
10:48:57     INFO -  TEST-INFO | (xpcshell/head.js) | test MAIN run_test finished (2)
10:48:57     INFO -  TEST-INFO | (xpcshell/head.js) | running event loop
10:48:57     INFO -  HTTPD-INFO | *** onSocketAccepted(socket=[xpconnect wrapped nsIServerSocket], trans=[xpconnect wrapped (nsISupports, nsISocketTransport, nsITransport, nsIDNSListener)])
10:48:57     INFO -  HTTPD-INFO | >>> new connection on 127.0.0.1:50249
10:48:57     INFO -  HTTPD-INFO | *** opening new connection 1 on port 50249
10:48:57     INFO -  HTTPD-INFO | *** starting connection 1
10:48:57     INFO -  HTTPD-INFO | *** onInputStreamReady(input=[xpconnect wrapped (nsISupports, nsIInputStream, nsIAsyncInputStream, nsISeekableStream, nsISearchableInputStream)]) on thread [xpconnect wrapped (nsISupports, nsIThread, nsIThreadInternal, nsIEventTarget, nsISupportsPriority)] (main is [xpconnect wrapped (nsISupports, nsIThread, nsIThreadInternal, nsIEventTarget, nsISupportsPriority)])
10:48:57     INFO -  HTTPD-INFO | *** this._state == 0
10:48:57     INFO -  HTTPD-INFO | *** _parseRequestLine('GET /thrower.sjs?throw HTTP/1.1')
10:48:57     INFO -  HTTPD-INFO | *** _parseHeaders
10:48:57     INFO -  HTTPD-INFO | *** Last name: 'undefined'
10:48:57     INFO -  HTTPD-INFO | *** Last val: 'undefined'
10:48:57     INFO -  HTTPD-INFO | *** Line text: 'Host: localhost:50914'

etc...

Comment 1

[Legacy TBPL/Treeherder Robot]

Tomcat
https://tbpl.mozilla.org/php/getParsedLog.php?id=37356568&tree=Mozilla-Inbound
Android 2.3 Emulator mozilla-inbound opt test xpcshell-1 on 2014-04-07 00:04:37
revision: fe57c073f019
slave: tst-linux64-spot-948

TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | Test timed out
TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | test failed (with xpcshell return code: -1), see following log:

Comment 2

[Legacy TBPL/Treeherder Robot]

Tomcat
https://tbpl.mozilla.org/php/getParsedLog.php?id=37439259&tree=Mozilla-Inbound
Android 2.3 Emulator mozilla-inbound opt test xpcshell-1 on 2014-04-08 04:23:27
revision: 4fbe5c6db773
slave: tst-linux64-spot-834

TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | Test timed out
TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | test failed (with xpcshell return code: -1), see following log:

Comment 3

[Geoff Brown [:gbrown]]

Successful runs on Android 2.3 are long-running, taking about 3 minutes to complete. The failure runs show continual progress for the 5+ minute duration:

05:56:29     INFO -  HTTPD-INFO | *** Normalized value: 'Tue, 08 Apr 2014 12:49:54 GMT'
...
05:56:33     INFO -  HTTPD-INFO | *** Normalized value: 'Tue, 08 Apr 2014 12:51:46 GMT'
...
05:56:38     INFO -  HTTPD-INFO | *** Normalized value: 'Tue, 08 Apr 2014 12:54:21 GMT'
...

Comment 4

[Geoff Brown [:gbrown]]

In contrast, this test completes in under 20 seconds on Android 2.2, Android 4.0, and Android x86 4.2.

Comment 5

[Geoff Brown [:gbrown]]

https://tbpl.mozilla.org/?tree=Try&rev=1bd881c44cdc forces the test to fail (to get the debug statements in logs) and adds httpd.js timestamps. The httpd logs suggest that nearly all operations take significantly longer on Android 2.3 (emulator on aws) than on any of the other platforms. Consider:

Android 2.2/tegra:

TEST-PASS | /mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/head_utils.js | [runHttpTests/listener.onStartRequest : 311] true == true
TEST-PASS | test_sjs_throwing_exceptions.js | [start_thrower : 60] 500 == 500
TEST-PASS | test_sjs_throwing_exceptions.js | [start_thrower : 61] false == false
TEST-INFO | (xpcshell/head.js) | test pending (2)
TEST-INFO | (xpcshell/head.js) | test finished (2)
HTTPD-INFO | 0:12.078 | *** onStopRequest async callback
HTTPD-INFO | 0:12.078 | *** onStopRequest [status=0x0]
HTTPD-INFO | 0:12.078 | *** closing connection 249 on port 49477
HTTPD-INFO | 0:12.093 | *** onSocketAccepted(socket=[xpconnect wrapped nsIServerSocket], trans=[xpconnect wrapped (nsISupports, nsISocketTransport, nsITransport, nsIDNSListener)])
HTTPD-INFO | 0:12.093 | >>> new connection on 127.0.0.1:49478
HTTPD-INFO | 0:12.094 | *** opening new connection 250 on port 49478
HTTPD-INFO | 0:12.094 | *** starting connection 250
HTTPD-INFO | 0:12.095 | *** onInputStreamReady(input=[xpconnect wrapped (nsISupports, nsIInputStream, nsIAsyncInputStream, nsISeekableStream, nsISearchableInputStream)]) on thread [xpconnect wrapped (nsISupports, nsIThread, nsIThreadInternal, nsIEventTarget, nsISupportsPriority)] (main is [xpconnect wrapped (nsISupports, nsIThread, nsIThreadInternal, nsIEventTarget, nsISupportsPriority)])
HTTPD-INFO | 0:12.096 | *** this._state == 0
HTTPD-INFO | 0:12.097 | *** _parseRequestLine('GET /thrower.sjs?throw HTTP/1.1')
HTTPD-INFO | 0:12.098 | *** _parseHeaders
HTTPD-INFO | 0:12.098 | *** Last name: 'undefined'
HTTPD-INFO | 0:12.098 | *** Last val: 'undefined'
HTTPD-INFO | 0:12.099 | *** Line text: 'Host: localhost:43477'
HTTPD-INFO | 0:12.099 | *** Last name: 'Host'
HTTPD-INFO | 0:12.099 | *** Last val: ' localhost:43477'
HTTPD-INFO | 0:12.099 | *** Line text: 'User-Agent: Mozilla/5.0 (Android; Mobile; rv:31.0) Gecko/31.0 Firefox/31.0'
HTTPD-INFO | 0:12.099 | *** Normalized value: 'localhost:43477'
HTTPD-INFO | 0:12.100 | *** Last name: 'User-Agent'
HTTPD-INFO | 0:12.100 | *** Last val: ' Mozilla/5.0 (Android; Mobile; rv:31.0) Gecko/31.0 Firefox/31.0'
HTTPD-INFO | 0:12.101 | *** Line text: 'Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'
HTTPD-INFO | 0:12.102 | *** Normalized value: 'Mozilla/5.0 (Android; Mobile; rv:31.0) Gecko/31.0 Firefox/31.0'
HTTPD-INFO | 0:12.102 | *** Last name: 'Accept'
HTTPD-INFO | 0:12.102 | *** Last val: ' text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'
HTTPD-INFO | 0:12.102 | *** Line text: 'Accept-Language: en-US,en;q=0.5'
HTTPD-INFO | 0:12.103 | *** Normalized value: 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'
HTTPD-INFO | 0:12.103 | *** Last name: 'Accept-Language'
HTTPD-INFO | 0:12.103 | *** Last val: ' en-US,en;q=0.5'
HTTPD-INFO | 0:12.104 | *** Line text: 'Accept-Encoding: gzip, deflate'
HTTPD-INFO | 0:12.104 | *** Normalized value: 'en-US,en;q=0.5'
HTTPD-INFO | 0:12.104 | *** Last name: 'Accept-Encoding'
HTTPD-INFO | 0:12.104 | *** Last val: ' gzip, deflate'
HTTPD-INFO | 0:12.105 | *** Line text: 'Connection: keep-alive'
HTTPD-INFO | 0:12.105 | *** Normalized value: 'gzip, deflate'
HTTPD-INFO | 0:12.105 | *** Last name: 'Connection'
HTTPD-INFO | 0:12.105 | *** Last val: ' keep-alive'
HTTPD-INFO | 0:12.105 | *** Line text: ''
HTTPD-INFO | 0:12.106 | *** Normalized value: 'keep-alive'
HTTPD-INFO | 0:12.106 | _processHeaders, Content-length=0
HTTPD-INFO | 0:12.106 | *** remaining body data len=0
HTTPD-INFO | 0:12.106 | *** _validateRequest
HTTPD-INFO | 0:12.106 | *** path == /thrower.sjs
HTTPD-INFO | 0:12.106 | *** _handleDefault()
HTTPD-INFO | 0:12.107 | *** handling '/thrower.sjs' as mapping to /mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/data/sjs/thrower.sjs from 0 to 155 inclusive
*** error running SJS at /mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/data/sjs/thrower.sjs: TypeError: undefined has no properties on line 4
HTTPD-INFO | 0:12.110 | *** partiallySent()
HTTPD-INFO | 0:12.110 | *** partiallySent()
HTTPD-INFO | 0:12.110 | *** errorCode == 500
HTTPD-INFO | 0:12.111 | *** Normalized value: 'text/html;charset=utf-8'
HTTPD-INFO | 0:12.111 | *** complete()
HTTPD-INFO | 0:12.111 | *** partiallySent()
HTTPD-INFO | 0:12.112 | *** _startAsyncProcessor()
HTTPD-INFO | 0:12.112 | *** _sendHeaders()
HTTPD-INFO | 0:12.112 | *** Normalized value: 'close'
HTTPD-INFO | 0:12.112 | *** Normalized value: 'httpd.js'
HTTPD-INFO | 0:12.112 | *** Normalized value: 'Tue, 08 Apr 2014 15:08:43 GMT'
HTTPD-INFO | 0:12.112 | *** non-async response, set Content-Length
HTTPD-INFO | 0:12.113 | *** Normalized value: '321'
HTTPD-INFO | 0:12.113 | *** header post-processing completed, sending response head...
HTTPD-INFO | 0:12.116 | *** preamble copying started
HTTPD-INFO | 0:12.116 | *** _waitToReadData
HTTPD-INFO | 0:12.116 | *** _waitForSinkClosure
HTTPD-INFO | 0:12.117 | *** onInputStreamReady
HTTPD-INFO | 0:12.117 | *** input wanted: 172
HTTPD-INFO | 0:12.117 | *** 172 bytes read
HTTPD-INFO | 0:12.118 | *** _waitToWriteData
HTTPD-INFO | 0:12.118 | *** _waitToReadData
HTTPD-INFO | 0:12.118 | *** onOutputStreamReady
HTTPD-INFO | 0:12.118 | *** wrote 172 bytes of data
HTTPD-INFO | 0:12.118 | *** _waitForSinkClosure
HTTPD-INFO | 0:12.119 | *** onInputStreamReady
HTTPD-INFO | 0:12.119 | *** input stream closed
HTTPD-INFO | 0:12.119 | *** _doneReadingSource(0x0)
HTTPD-INFO | 0:12.119 | *** _finishSource(0)
HTTPD-INFO | 0:12.119 | *** _cancelOrDispatchCancelCallback(0)
HTTPD-INFO | 0:12.119 | *** cancel(0)
HTTPD-INFO | 0:12.119 | *** _doneReadingSource(0x0)
HTTPD-INFO | 0:12.119 | *** _finishSource(0)
HTTPD-INFO | 0:12.119 | *** _cancelOrDispatchCancelCallback(0)
HTTPD-INFO | 0:12.120 | *** onStopRequest async callback
HTTPD-INFO | 0:12.120 | *** preamble copying complete [status=0x0]
HTTPD-INFO | 0:12.120 | *** _sendBody
HTTPD-INFO | 0:12.120 | *** starting async copier of body data...
HTTPD-INFO | 0:12.120 | *** onStartRequest
HTTPD-INFO | 0:12.120 | *** _waitToReadData
HTTPD-INFO | 0:12.120 | *** _waitForSinkClosure
HTTPD-INFO | 0:12.121 | *** onInputStreamReady
HTTPD-INFO | 0:12.121 | *** input wanted: 321
HTTPD-INFO | 0:12.122 | *** 321 bytes read
HTTPD-INFO | 0:12.122 | *** _waitToWriteData
HTTPD-INFO | 0:12.122 | *** _waitToReadData
HTTPD-INFO | 0:12.122 | *** onOutputStreamReady
HTTPD-INFO | 0:12.122 | *** wrote 321 bytes of data
HTTPD-INFO | 0:12.122 | *** _waitForSinkClosure
HTTPD-INFO | 0:12.123 | *** onInputStreamReady
HTTPD-INFO | 0:12.123 | *** input stream closed
HTTPD-INFO | 0:12.123 | *** _doneReadingSource(0x0)
HTTPD-INFO | 0:12.123 | *** _finishSource(0)
HTTPD-INFO | 0:12.123 | *** _cancelOrDispatchCancelCallback(0)
HTTPD-INFO | 0:12.123 | *** cancel(0)
HTTPD-INFO | 0:12.123 | *** _doneReadingSource(0x0)
HTTPD-INFO | 0:12.123 | *** _finishSource(0)
HTTPD-INFO | 0:12.124 | *** _cancelOrDispatchCancelCallback(0)
TEST-PASS | /mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/head_utils.js | [runHttpTests/listener.onStartRequest : 311] true == true
TEST-PASS | test_sjs_throwing_exceptions.js | [start_thrower : 60] 500 == 500
TEST-PASS | test_sjs_throwing_exceptions.js | [start_thrower : 61] false == false
TEST-INFO | (xpcshell/head.js) | test pending (2)
TEST-INFO | (xpcshell/head.js) | test finished (2)

Android 2.3/emulator on aws:

15:06:50     INFO -  TEST-PASS | /mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/head_utils.js | [runHttpTests/listener.onStartRequest : 311] true == true
15:06:50     INFO -  TEST-PASS | test_sjs_throwing_exceptions.js | [start_thrower : 60] 500 == 500
15:06:50     INFO -  TEST-PASS | test_sjs_throwing_exceptions.js | [start_thrower : 61] false == false
15:06:50     INFO -  TEST-INFO | (xpcshell/head.js) | test pending (2)
15:06:50     INFO -  TEST-INFO | (xpcshell/head.js) | test finished (2)
15:06:50     INFO -  HTTPD-INFO | 3:12.488 | *** onStopRequest async callback
15:06:50     INFO -  HTTPD-INFO | 3:12.489 | *** onStopRequest [status=0x0]
15:06:50     INFO -  HTTPD-INFO | 3:12.491 | *** closing connection 243 on port 38185
15:06:50     INFO -  HTTPD-INFO | 3:12.565 | *** onSocketAccepted(socket=[xpconnect wrapped nsIServerSocket], trans=[xpconnect wrapped (nsISupports, nsISocketTransport, nsITransport, nsIDNSListener)])
15:06:50     INFO -  HTTPD-INFO | 3:12.567 | >>> new connection on 127.0.0.1:38186
15:06:50     INFO -  HTTPD-INFO | 3:12.578 | *** opening new connection 244 on port 38186
15:06:50     INFO -  HTTPD-INFO | 3:12.588 | *** starting connection 244
15:06:50     INFO -  HTTPD-INFO | 3:12.606 | *** onInputStreamReady(input=[xpconnect wrapped (nsISupports, nsIInputStream, nsIAsyncInputStream, nsISeekableStream, nsISearchableInputStream)]) on thread [xpconnect wrapped (nsISupports, nsIThread, nsIThreadInternal, nsIEventTarget, nsISupportsPriority)] (main is [xpconnect wrapped (nsISupports, nsIThread, nsIThreadInternal, nsIEventTarget, nsISupportsPriority)])
15:06:50     INFO -  HTTPD-INFO | 3:12.607 | *** this._state == 0
15:06:50     INFO -  HTTPD-INFO | 3:12.632 | *** _parseRequestLine('GET /thrower.sjs?throw HTTP/1.1')
15:06:50     INFO -  HTTPD-INFO | 3:12.640 | *** _parseHeaders
15:06:50     INFO -  HTTPD-INFO | 3:12.641 | *** Last name: 'undefined'
15:06:50     INFO -  HTTPD-INFO | 3:12.644 | *** Last val: 'undefined'
15:06:50     INFO -  HTTPD-INFO | 3:12.659 | *** Line text: 'Host: localhost:54972'
15:06:50     INFO -  HTTPD-INFO | 3:12.661 | *** Last name: 'Host'
15:06:50     INFO -  HTTPD-INFO | 3:12.663 | *** Last val: ' localhost:54972'
15:06:50     INFO -  HTTPD-INFO | 3:12.671 | *** Line text: 'User-Agent: Mozilla/5.0 (Android; Mobile; rv:31.0) Gecko/31.0 Firefox/31.0'
15:06:50     INFO -  HTTPD-INFO | 3:12.683 | *** Normalized value: 'localhost:54972'
15:06:50     INFO -  HTTPD-INFO | 3:12.697 | *** Last name: 'User-Agent'
15:06:50     INFO -  HTTPD-INFO | 3:12.697 | *** Last val: ' Mozilla/5.0 (Android; Mobile; rv:31.0) Gecko/31.0 Firefox/31.0'
15:06:50     INFO -  HTTPD-INFO | 3:12.711 | *** Line text: 'Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'
15:06:50     INFO -  HTTPD-INFO | 3:12.716 | *** Normalized value: 'Mozilla/5.0 (Android; Mobile; rv:31.0) Gecko/31.0 Firefox/31.0'
15:06:50     INFO -  HTTPD-INFO | 3:12.721 | *** Last name: 'Accept'
15:06:50     INFO -  HTTPD-INFO | 3:12.723 | *** Last val: ' text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'
15:06:50     INFO -  HTTPD-INFO | 3:12.728 | *** Line text: 'Accept-Language: en-US,en;q=0.5'
15:06:50     INFO -  HTTPD-INFO | 3:12.743 | *** Normalized value: 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'
15:06:50     INFO -  HTTPD-INFO | 3:12.745 | *** Last name: 'Accept-Language'
15:06:50     INFO -  HTTPD-INFO | 3:12.747 | *** Last val: ' en-US,en;q=0.5'
15:06:50     INFO -  HTTPD-INFO | 3:12.752 | *** Line text: 'Accept-Encoding: gzip, deflate'
15:06:50     INFO -  HTTPD-INFO | 3:12.757 | *** Normalized value: 'en-US,en;q=0.5'
15:06:50     INFO -  HTTPD-INFO | 3:12.759 | *** Last name: 'Accept-Encoding'
15:06:50     INFO -  HTTPD-INFO | 3:12.760 | *** Last val: ' gzip, deflate'
15:06:50     INFO -  HTTPD-INFO | 3:12.762 | *** Line text: 'Connection: keep-alive'
15:06:50     INFO -  HTTPD-INFO | 3:12.765 | *** Normalized value: 'gzip, deflate'
15:06:50     INFO -  HTTPD-INFO | 3:12.768 | *** Last name: 'Connection'
15:06:50     INFO -  HTTPD-INFO | 3:12.772 | *** Last val: ' keep-alive'
15:06:50     INFO -  HTTPD-INFO | 3:12.780 | *** Line text: ''
15:06:50     INFO -  HTTPD-INFO | 3:12.782 | *** Normalized value: 'keep-alive'
15:06:50     INFO -  HTTPD-INFO | 3:12.786 | _processHeaders, Content-length=0
15:06:50     INFO -  HTTPD-INFO | 3:12.789 | *** remaining body data len=0
15:06:50     INFO -  HTTPD-INFO | 3:12.792 | *** _validateRequest
15:06:50     INFO -  HTTPD-INFO | 3:12.808 | *** path == /thrower.sjs
15:06:50     INFO -  HTTPD-INFO | 3:12.810 | *** _handleDefault()
15:06:50     INFO -  HTTPD-INFO | 3:12.823 | *** handling '/thrower.sjs' as mapping to /mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/data/sjs/thrower.sjs from 0 to 155 inclusive
15:06:50     INFO -  *** error running SJS at /mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/data/sjs/thrower.sjs: TypeError: undefined has no properties on line 4
15:06:50     INFO -  HTTPD-INFO | 3:12.845 | *** partiallySent()
15:06:50     INFO -  HTTPD-INFO | 3:12.848 | *** partiallySent()
15:06:50     INFO -  HTTPD-INFO | 3:12.848 | *** errorCode == 500
15:06:50     INFO -  HTTPD-INFO | 3:12.870 | *** Normalized value: 'text/html;charset=utf-8'
15:06:50     INFO -  HTTPD-INFO | 3:12.875 | *** complete()
15:06:50     INFO -  HTTPD-INFO | 3:12.878 | *** partiallySent()
15:06:50     INFO -  HTTPD-INFO | 3:12.881 | *** _startAsyncProcessor()
15:06:50     INFO -  HTTPD-INFO | 3:12.881 | *** _sendHeaders()
15:06:50     INFO -  HTTPD-INFO | 3:12.885 | *** Normalized value: 'close'
15:06:50     INFO -  HTTPD-INFO | 3:12.886 | *** Normalized value: 'httpd.js'
15:06:50     INFO -  HTTPD-INFO | 3:12.891 | *** Normalized value: 'Tue, 08 Apr 2014 21:50:31 GMT'
15:06:50     INFO -  HTTPD-INFO | 3:12.893 | *** non-async response, set Content-Length
15:06:50     INFO -  HTTPD-INFO | 3:12.902 | *** Normalized value: '321'
15:06:50     INFO -  HTTPD-INFO | 3:12.903 | *** header post-processing completed, sending response head...
15:06:50     INFO -  HTTPD-INFO | 3:12.941 | *** preamble copying started
15:06:50     INFO -  HTTPD-INFO | 3:12.942 | *** _waitToReadData
15:06:50     INFO -  HTTPD-INFO | 3:12.947 | *** _waitForSinkClosure
15:06:50     INFO -  HTTPD-INFO | 3:12.954 | *** onInputStreamReady
15:06:50     INFO -  HTTPD-INFO | 3:12.958 | *** input wanted: 172
15:06:50     INFO -  HTTPD-INFO | 3:12.963 | *** 172 bytes read
15:06:50     INFO -  HTTPD-INFO | 3:12.965 | *** _waitToWriteData
15:06:50     INFO -  HTTPD-INFO | 3:12.969 | *** _waitToReadData
15:06:50     INFO -  HTTPD-INFO | 3:12.974 | *** onOutputStreamReady
15:06:50     INFO -  HTTPD-INFO | 3:12.982 | *** wrote 172 bytes of data
15:06:50     INFO -  HTTPD-INFO | 3:12.984 | *** _waitForSinkClosure
15:06:50     INFO -  HTTPD-INFO | 3:12.996 | *** onInputStreamReady
15:06:50     INFO -  HTTPD-INFO | 3:12.999 | *** input stream closed
15:06:50     INFO -  HTTPD-INFO | 3:13.001 | *** _doneReadingSource(0x0)
15:06:50     INFO -  HTTPD-INFO | 3:13.001 | *** _finishSource(0)
15:06:50     INFO -  HTTPD-INFO | 3:13.003 | *** _cancelOrDispatchCancelCallback(0)
15:06:50     INFO -  HTTPD-INFO | 3:13.035 | *** cancel(0)
15:06:50     INFO -  HTTPD-INFO | 3:13.038 | *** _doneReadingSource(0x0)
15:06:50     INFO -  HTTPD-INFO | 3:13.040 | *** _finishSource(0)
15:06:50     INFO -  HTTPD-INFO | 3:13.041 | *** _cancelOrDispatchCancelCallback(0)
15:06:50     INFO -  HTTPD-INFO | 3:13.049 | *** onStopRequest async callback
15:06:50     INFO -  HTTPD-INFO | 3:13.050 | *** preamble copying complete [status=0x0]
15:06:50     INFO -  HTTPD-INFO | 3:13.051 | *** _sendBody
15:06:50     INFO -  HTTPD-INFO | 3:13.055 | *** starting async copier of body data...
15:06:50     INFO -  HTTPD-INFO | 3:13.058 | *** onStartRequest
15:06:50     INFO -  HTTPD-INFO | 3:13.063 | *** _waitToReadData
15:06:50     INFO -  HTTPD-INFO | 3:13.066 | *** _waitForSinkClosure
15:06:50     INFO -  HTTPD-INFO | 3:13.087 | *** onInputStreamReady
15:06:50     INFO -  HTTPD-INFO | 3:13.097 | *** input wanted: 321
15:06:50     INFO -  HTTPD-INFO | 3:13.102 | *** 321 bytes read
15:06:50     INFO -  HTTPD-INFO | 3:13.110 | *** _waitToWriteData
15:06:50     INFO -  HTTPD-INFO | 3:13.114 | *** _waitToReadData
15:06:50     INFO -  HTTPD-INFO | 3:13.127 | *** onOutputStreamReady
15:06:50     INFO -  HTTPD-INFO | 3:13.145 | *** wrote 321 bytes of data
15:06:50     INFO -  HTTPD-INFO | 3:13.146 | *** _waitForSinkClosure
15:06:50     INFO -  HTTPD-INFO | 3:13.165 | *** onInputStreamReady
15:06:50     INFO -  HTTPD-INFO | 3:13.167 | *** input stream closed
15:06:50     INFO -  HTTPD-INFO | 3:13.170 | *** _doneReadingSource(0x0)
15:06:50     INFO -  HTTPD-INFO | 3:13.171 | *** _finishSource(0)
15:06:50     INFO -  HTTPD-INFO | 3:13.175 | *** _cancelOrDispatchCancelCallback(0)
15:06:50     INFO -  HTTPD-INFO | 3:13.178 | *** cancel(0)
15:06:50     INFO -  HTTPD-INFO | 3:13.180 | *** _doneReadingSource(0x0)
15:06:50     INFO -  HTTPD-INFO | 3:13.181 | *** _finishSource(0)
15:06:50     INFO -  HTTPD-INFO | 3:13.181 | *** _cancelOrDispatchCancelCallback(0)
15:06:50     INFO -  TEST-PASS | /mnt/sdcard/tests/xpcshell/netwerk/test/httpserver/test/head_utils.js | [runHttpTests/listener.onStartRequest : 311] true == true
15:06:50     INFO -  TEST-PASS | test_sjs_throwing_exceptions.js | [start_thrower : 60] 500 == 500
15:06:50     INFO -  TEST-PASS | test_sjs_throwing_exceptions.js | [start_thrower : 61] false == false
15:06:50     INFO -  TEST-INFO | (xpcshell/head.js) | test pending (2)
15:06:50     INFO -  TEST-INFO | (xpcshell/head.js) | test finished (2)

Comment 6

[Legacy TBPL/Treeherder Robot]

Tomcat
https://tbpl.mozilla.org/php/getParsedLog.php?id=37557500&tree=Mozilla-Inbound
Android 2.3 Emulator mozilla-inbound opt test xpcshell-1 on 2014-04-10 01:58:08
revision: 7906728a1b88
slave: tst-linux64-spot-843

TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | test failed (with xpcshell return code: 139), see following log:
PROCESS-CRASH | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | application crashed [@ 0x0]

Comment 7

[Legacy TBPL/Treeherder Robot]

RyanVM
https://tbpl.mozilla.org/php/getParsedLog.php?id=38601897&tree=Fx-Team
Android 4.0 Panda fx-team opt test xpcshell on 2014-04-27 19:21:18
revision: d78338aed492
slave: panda-0634

TEST-UNEXPECTED-FAIL | /builds/panda-0634/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | Test timed out
AttributeError: 'NoneType' object has no attribute 'recv'
AttributeError: 'NoneType' object has no attribute 'recv'
Return code: 1

Comment 8

[Geoff Brown [:gbrown]]

(In reply to TBPL Robot from comment #6)
> https://tbpl.mozilla.org/php/getParsedLog.php?id=37557500&tree=Mozilla-Inbound

This one was bug 985155.

Comment 9

[Legacy TBPL/Treeherder Robot]

KWierso
https://tbpl.mozilla.org/php/getParsedLog.php?id=38656438&tree=Mozilla-Inbound
Android 2.3 Emulator mozilla-inbound opt test xpcshell-1 on 2014-04-28 12:00:30
revision: 3aa6bab70380
slave: tst-linux64-spot-145

TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | Test timed out
TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | test failed (with xpcshell return code: -1), see following log:

Comment 10

[Legacy TBPL/Treeherder Robot]

Tomcat
https://tbpl.mozilla.org/php/getParsedLog.php?id=40169643&tree=Mozilla-Inbound
Android 2.2 Tegra mozilla-inbound opt test xpcshell on 2014-05-22 00:37:43
revision: 6c25b11dbef0
slave: tegra-052

TEST-UNEXPECTED-FAIL | /builds/tegra-052/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | Test timed out
TEST-UNEXPECTED-FAIL | /builds/tegra-052/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | test failed (with xpcshell return code: -1), see following log:
Automation Error: No crash directory (/mnt/sdcard/tests/xpcshell/minidumps) found on remote device
TEST-UNEXPECTED-FAIL | /builds/tegra-052/test/build/tests/xpcshell/tests/services/common/tests/unit/test_utils_dateprefs.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | resource://services-common/utils.js | Error: Trying to set test00 to a very old time: Thu Jan 01 1970 00:02:31 GMT+0000 (GMT). The current time is Thu Jan 01 1970 00:02:31 GMT+0000 (GMT). Is the system clock wrong? at resource://services-common/utils.js:585 - See following stack:
TEST-UNEXPECTED-FAIL | /builds/tegra-052/test/build/tests/xpcshell/tests/services/common/tests/unit/test_hawkclient.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | test_hawkclient.js | 1 == 2 - See following stack:
TEST-UNEXPECTED-FAIL | /mnt/sdcard/tests/xpcshell/head.js | Unexpected exception 2147500036
TEST-UNEXPECTED-FAIL | /builds/tegra-052/test/build/tests/xpcshell/tests/services/common/tests/unit/test_storageservice_client.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | resource://services-common/utils.js | Error: Timestamp appears to be in seconds: 205648 at resource://services-common/utils.js:437 - See following stack:
TEST-UNEXPECTED-FAIL | /builds/tegra-052/test/build/tests/xpcshell/tests/services/common/tests/unit/test_storage_server.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | resource://services-common/utils.js | Error: Timestamp appears to be in seconds: 211753 at resource://services-common/utils.js:437 - See following stack:
TEST-UNEXPECTED-FAIL | /builds/tegra-052/test/build/tests/xpcshell/tests/security/manager/ssl/tests/unit/test_sts_preloadlist_selfdestruct.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | test_sts_preloadlist_selfdestruct.js | true == false - See following stack:
TEST-UNEXPECTED-FAIL | /builds/tegra-052/test/build/tests/xpcshell/tests/security/manager/ssl/tests/unit/test_certificate_usages.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | test_certificate_usages.js | "SSL CA" == "" - See following stack:
TEST-UNEXPECTED-FAIL | /builds/tegra-052/test/build/tests/xpcshell/tests/security/manager/ssl/tests/unit/test_cert_signatures.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | test_cert_signatures.js | "SSL CA" == "" - See following stack:
TEST-UNEXPECTED-FAIL | /builds/tegra-052/test/build/tests/xpcshell/tests/security/manager/ssl/tests/unit/test_getchain.js | test failed (with xpcshell return code: 0), see following log:
TEST-UNEXPECTED-FAIL | test_getchain.js | "01" == "02" - See following stack:
Only displaying first 20 of 32 failures -
.

Comment 11

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-10-05T19:47:30
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=mozilla-aurora&job_id=295708
repository: mozilla-aurora
who: philringnalda[at]gmail[dot]com
machine: tst-linux64-spot-157
buildname: Android 2.3 Emulator mozilla-aurora opt test xpcshell-2
revision: 701fcc5fcce9

TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | Test timed out
DMError: Invalid process line: HTTPD-INFO | *** Normalized value: 'localhost:46739'
TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | test failed (with xpcshell return code: -1), see following log:

Comment 12

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-11-05T07:32:49
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=mozilla-aurora&job_id=369302
repository: mozilla-aurora
who: rvandermeulen[at]mozilla[dot]com
machine: tst-linux64-spot-056
buildname: Android 2.3 Emulator mozilla-aurora opt test xpcshell-1
revision: 75158d5c8acd

TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | Test timed out
DMError: Invalid process line: HTTPD-INFO | *** _waitForSinkClosure
TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | test failed (with xpcshell return code: -1), see following log:
TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_URIs.js | Test timed out
DMError: Invalid process line: {"source_file":"test_URIs.js","test_name":"do_check_uri_eqExceptRef","line_number":340,"diagnostic":"[do_check_uri_eqExceptRef : 340] true == true\n","action":"test_pass","_time":1415195499572}
TEST-UNEXPECTED-FAIL | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_URIs.js | test failed (with xpcshell return code: -1), see following log:

Comment 13

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-11-30T07:40:16
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=mozilla-inbound&job_id=4308952
repository: mozilla-inbound
who: philringnalda[at]gmail[dot]com
machine: tst-linux64-spot-829
buildname: Android 2.3 Emulator mozilla-inbound opt test xpcshell-1
revision: 727de0929cca

TEST-UNEXPECTED-TIMEOUT | /builds/slave/test/build/tests/xpcshell/tests/netwerk/test/httpserver/test/test_sjs_throwing_exceptions.js | Test timed out
DMError: Invalid process line: HTTPD-INFO | *** _handleDefault()
TEST-UNEXPECTED-FAIL | Received SIGINT (control-C), so stopped run. (Use --keep-going to keep running tests after killing one with SIGINT)

Comment 14

[Ed Morley [:emorley]]

Inactive; closing (see bug 1180138).