Closed Bug 1140656 Opened 11 years ago Closed 5 years ago

Intermittent test_socks.js | xpcshell return code: 0

Categories

(Core :: Networking, defect, P3)

39 Branch
x86_64
macOS
defect

Tracking

()

RESOLVED WORKSFORME
Tracking Status
firefox37 --- unaffected
firefox38 --- affected
firefox39 --- affected
firefox-esr31 --- unaffected

People

(Reporter: KWierso, Unassigned)

References

Details

(Keywords: intermittent-failure, regression, Whiteboard: [necko-backlog][stockwell disabled])

Attachments

(1 file)

15:00:32 INFO - TEST-START | uriloader/exthandler/tests/unit/test_handlerService.js 15:00:32 INFO - TEST-PASS | uriloader/exthandler/tests/unit/test_handlerService.js | took 242ms 15:00:32 INFO - TEST-START | uriloader/exthandler/tests/unit/test_punycodeURIs.js 15:00:33 INFO - TEST-PASS | uriloader/exthandler/tests/unit/test_punycodeURIs.js | took 176ms 15:00:33 INFO - Retrying tests that failed when run in parallel. 15:00:33 INFO - TEST-START | netwerk/test/unit/test_socks.js 15:02:33 WARNING - TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_socks.js | xpcshell return code: 0 15:02:33 INFO - TEST-INFO took 120205ms 15:02:33 INFO - >>>>>>> 15:02:33 INFO - (xpcshell/head.js) | test MAIN run_test pending (1) 15:02:33 INFO - PROCESS | 5664 | server: listening on 57359 15:02:33 INFO - PROCESS | 5664 | server: using test case socks4|57359|127.0.0.1|8000|local 15:02:33 INFO - PROCESS | 5664 | server: using test case socks4|57359|12345.xxx|8001|remote 15:02:33 INFO - PROCESS | 5664 | server: using test case socks4|57359|::1|8002|local 15:02:33 INFO - PROCESS | 5664 | server: using test case socks|57359|127.0.0.1|8003|local 15:02:33 INFO - PROCESS | 5664 | server: using test case socks|57359|abcdefg.xxx|8004|remote 15:02:33 INFO - PROCESS | 5664 | server: using test case socks|57359|::1|8005|local 15:02:33 INFO - (xpcshell/head.js) | test pending (2) 15:02:33 INFO - (xpcshell/head.js) | test MAIN run_test finished (2) 15:02:33 INFO - running event loop 15:02:33 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "TypeError: variable script redeclares argument" {file: "/builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_socks.js" line: 39 column: 6 source: " var script = do_get_file(script); 15:02:33 INFO - "}]" 15:02:33 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "TypeError: variable args redeclares argument" {file: "/builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_socks.js" line: 41 column: 6 source: " var args = [script.path].concat(args); 15:02:33 INFO - "}]" 15:02:33 INFO - PROCESS | 5664 | client: running test socks4|57359|127.0.0.1|8000|local 15:02:33 INFO - PROCESS | 5664 | server: got client connection 15:02:33 INFO - PROCESS | 5664 | server: got socks 4 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksClient.prototype.checkSocks4Request - [SocksClient.prototype.checkSocks4Request : 209] 1 == 1 15:02:33 INFO - PROCESS | 5664 | server: sending ping 15:02:33 INFO - PROCESS | 5664 | client: got ping, sending pong. 15:02:33 INFO - PROCESS | 5664 | client: running test socks4|57359|12345.xxx|8001|remote 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksClient.prototype.checkPong - [SocksClient.prototype.checkPong : 359] "PONG!" == "PONG!" 15:02:33 INFO - PROCESS | 5664 | server: got client connection 15:02:33 INFO - PROCESS | 5664 | server: got socks 4 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksClient.prototype.checkSocks4Request - [SocksClient.prototype.checkSocks4Request : 209] 1 == 1 15:02:33 INFO - PROCESS | 5664 | server: sending ping 15:02:33 INFO - PROCESS | 5664 | client: got ping, sending pong. 15:02:33 INFO - PROCESS | 5664 | client: running test socks4|57359|::1|8002|local 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksClient.prototype.checkPong - [SocksClient.prototype.checkPong : 359] "PONG!" == "PONG!" 15:02:33 INFO - SOCKS test took too long! 15:02:33 INFO - /builds/slave/talos-slave/test/build/tests/xpcshell/tests/netwerk/test/unit/test_socks.js:test_timeout:483 15:02:33 INFO - /builds/slave/talos-slave/test/build/tests/xpcshell/head.js:_Timer.prototype.notify:183 15:02:33 INFO - /builds/slave/talos-slave/test/build/tests/xpcshell/head.js:_do_main:207 15:02:33 INFO - /builds/slave/talos-slave/test/build/tests/xpcshell/head.js:_execute_test:505 15:02:33 INFO - -e:null:1 15:02:33 INFO - null:null:0 15:02:33 INFO - exiting test 15:02:33 INFO - exception thrown from do_timeout callback: 2147500036 15:02:33 INFO - /builds/slave/talos-slave/test/build/tests/xpcshell/head.js:_Timer.prototype.notify:185 15:02:33 INFO - /builds/slave/talos-slave/test/build/tests/xpcshell/head.js:_do_main:207 15:02:33 INFO - /builds/slave/talos-slave/test/build/tests/xpcshell/head.js:_execute_test:505 15:02:33 INFO - -e:null:1 15:02:33 INFO - null:null:0 15:02:33 INFO - exiting test 15:02:33 INFO - PROCESS | 5664 | server: client closed! 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksClient.prototype.onInputStreamReady - [SocksClient.prototype.onInputStreamReady : 120] 8 == 8 15:02:33 INFO - PROCESS | 5664 | server: test finished 8001 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksTestServer.prototype.testCompleted - [SocksTestServer.prototype.testCompleted : 410] true == true 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksTestServer.prototype.testCompleted - [SocksTestServer.prototype.testCompleted : 411] "socks4" == "socks4" 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksTestServer.prototype.testCompleted - [SocksTestServer.prototype.testCompleted : 412] 8001 == 8001 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksTestServer.prototype.testCompleted - [SocksTestServer.prototype.testCompleted : 415] "12345.xxx" == "12345.xxx" 15:02:33 INFO - PROCESS | 5664 | server: client closed! 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksClient.prototype.onInputStreamReady - [SocksClient.prototype.onInputStreamReady : 120] 8 == 8 15:02:33 INFO - PROCESS | 5664 | server: test finished 8000 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksTestServer.prototype.testCompleted - [SocksTestServer.prototype.testCompleted : 410] true == true 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksTestServer.prototype.testCompleted - [SocksTestServer.prototype.testCompleted : 411] "socks4" == "socks4" 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksTestServer.prototype.testCompleted - [SocksTestServer.prototype.testCompleted : 412] 8000 == 8000 15:02:33 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | SocksTestServer.prototype.testCompleted - [SocksTestServer.prototype.testCompleted : 417] "127.0.0.1" == "127.0.0.1" 15:02:33 INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Error: "uncaught exception: 2147500036"]" 15:02:33 INFO - <<<<<<< 15:02:33 INFO - TEST-START | services/sync/tests/unit/test_errorhandler.js 15:02:51 INFO - TEST-PASS | services/sync/tests/unit/test_errorhandler.js | took 18006ms 15:02:51 INFO - TEST-START | toolkit/components/search/tests/xpcshell/test_location_error.js 15:02:51 INFO - TEST-PASS | toolkit/components/search/tests/xpcshell/test_location_error.js | took 451ms 15:02:51 INFO - INFO | Result summary: 15:02:51 INFO - INFO | Passed: 2349 15:02:51 WARNING - INFO | Failed: 1 15:02:51 WARNING - One or more unittests failed. 15:02:51 INFO - INFO | Todo: 4 15:02:51 INFO - INFO | Retried: 3 15:02:51 INFO - SUITE-END | took 716s 15:02:51 ERROR - Return code: 1
Pretty frequent 10.10 failure.
Flags: needinfo?(mcmanus)
dragana - I wonder if there is something racy in the test tickled by https://bugzilla.mozilla.org/show_bug.cgi?id=1131557
Flags: needinfo?(mcmanus) → needinfo?(dd.mozilla)
I do not really see nothing racy. It looks like that a client creates a transport to connect to the server but the server never gets the tcp syn or fails accepting the connection. I will try to reproduce it tomorrow. Apple app store has not been accessible today, so I couldn't upgrade my mac to 10.10.
Flags: needinfo?(dd.mozilla)
Assignee: nobody → dd.mozilla
Status: NEW → ASSIGNED
This is near permafail on Aurora now that 10.10 debug tests were turned on there.
Hi Nick, if you have time, can you take a look at test_socks on osx 10.10 with mozilla-central. It doesn't fail on the debug build and it does not fail with the logging turned on. I have put some logging only in 2-3 places and i have got it to fail and from a log it looked like it's had never got out of Poll() function (http://mxr.mozilla.org/mozilla-central/source/netwerk/base/nsSocketTransportService2.cpp#1000). It can be that it had returned from the function but just not showing log (or hangs in the log). You were looking into poll hangs on osx, i am not sure it is the same thing. It can be connected to other bugs with xpcshell tests on osx 10.10 (probably some bugs have the same problem).
Flags: needinfo?(hurley)
So I've looked into this, and reproduced but once (sadly not with anything useful, like logging, or under a debugger), but based on Dragana's description of this never *leaving* Poll, this doesn't sound quite the same as the issue I was looking into (which is Poll returns an error all the time, causing a tight spin in nsSocketTransportService::Run). As I continue digging into the other issue, though, I'll keep this one in mind as well to see if they are, in fact, somehow related.
Flags: needinfo?(hurley)
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → WORKSFORME
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Whiteboard: [necko-backlog]
Bulk assigning P3 to all open intermittent bugs without a priority set in Firefox components per bug 1298978.
Priority: -- → P3
Assignee: dd.mozilla → nobody
Priority: P3 → P1
Priority: P1 → P3

There are 24 total failures in the last 7 days on osx-10-10: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-19&endday=2019-04-26&tree=trunk&bug=1140656

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=242785096&repo=autoland&lineNumber=7816

02:25:31 INFO - TEST-START | netwerk/test/unit/test_socks.js
02:27:31 WARNING - TEST-UNEXPECTED-FAIL | netwerk/test/unit/test_socks.js | xpcshell return code: 0
02:27:31 INFO - TEST-INFO took 120354ms
02:27:31 INFO - >>>>>>>
02:27:31 INFO - PID 7679 | [7679, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, NS_ERROR_UNEXPECTED) failed with result 0x80004005: file /builds/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 1026
02:27:31 INFO - PID 7679 | [7679, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/workspace/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2528
02:27:31 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
02:27:31 INFO - PID 7679 | server: listening on 59346
02:27:31 INFO - PID 7679 | server: using test case socks4|59346|127.0.0.1|8000|local
02:27:31 INFO - PID 7679 | server: using test case socks4|59346|12345.xxx|8001|remote
02:27:31 INFO - PID 7679 | server: using test case socks4|59346|::1|8002|local
02:27:31 INFO - PID 7679 | server: using test case socks|59346|127.0.0.1|8003|local
02:27:31 INFO - PID 7679 | server: using test case socks|59346|abcdefg.xxx|8004|remote
02:27:31 INFO - PID 7679 | server: using test case socks|59346|::1|8005|local
02:27:31 INFO - (xpcshell/head.js) | test pending (2)
02:27:31 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
02:27:31 INFO - running event loop
02:27:31 INFO - PID 7679 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
02:27:31 INFO - PID 7679 | [7679, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/workspace/build/src/dom/media/CubebUtils.cpp, line 385
02:27:31 INFO - "CONSOLE_MESSAGE: (info) No chrome package registered for chrome://branding/locale/brand.properties"
02:27:31 INFO - PID 7679 | [7680, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, NS_ERROR_UNEXPECTED) failed with result 0x80004005: file /builds/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 1026
02:27:31 INFO - PID 7679 | client: running test socks4|59346|127.0.0.1|8000|local
02:27:31 INFO - PID 7679 | server: got client connection
02:27:31 INFO - PID 7679 | server: got socks 4
02:27:31 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | checkSocks4Request - [checkSocks4Request : 209] 1 == 1
02:27:31 INFO - PID 7679 | server: sending ping
02:27:31 INFO - PID 7679 | client: got ping, sending pong.
02:27:31 INFO - PID 7679 | client: running test socks4|59346|12345.xxx|8001|remote
02:27:31 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | checkPong - [checkPong : 359] "PONG!" == "PONG!"
02:27:31 INFO - PID 7679 | server: got client connection
02:27:31 INFO - PID 7679 | server: got socks 4
02:27:31 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | checkSocks4Request - [checkSocks4Request : 209] 1 == 1
02:27:31 INFO - PID 7679 | server: sending ping
02:27:31 INFO - PID 7679 | client: got ping, sending pong.
02:27:31 INFO - PID 7679 | client: running test socks4|59346|::1|8002|local
02:27:31 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | checkPong - [checkPong : 359] "PONG!" == "PONG!"
02:27:31 INFO - PID 7679 | server: got client connection
02:27:31 INFO - PID 7679 | server: got socks 5
02:27:31 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | checkSocks5Greeting - [checkSocks5Greeting : 277] true == true
02:27:31 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | checkSocks5Greeting - [checkSocks5Greeting : 279] true == true
02:27:31 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | checkSocks5Request - [checkSocks5Request : 291] 5 == 5
02:27:31 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | checkSocks5Request - [checkSocks5Request : 292] 1 == 1
02:27:31 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | checkSocks5Request - [checkSocks5Request : 293] 0 == 0
02:27:31 INFO - PID 7679 | server: sending ping
02:27:31 INFO - PID 7679 | client: got ping, sending pong.
02:27:31 INFO - PID 7679 | client: running test socks|59346|127.0.0.1|8003|local
02:27:31 INFO - TEST-PASS | netwerk/test/unit/test_socks.js | checkPong - [checkPong : 359] "PONG!" == "PONG!"
02:27:31 INFO - SOCKS test took too long!
02:27:31 INFO - /Users/cltbld/tasks/task_1556242733/build/tests/xpcshell/tests/netwerk/test/unit/test_socks.js:test_timeout:483
02:27:31 INFO - /Users/cltbld/tasks/task_1556242733/build/tests/xpcshell/head.js:notify:201
02:27:31 INFO - /Users/cltbld/tasks/task_1556242733/build/tests/xpcshell/head.js:_do_main:227
02:27:31 INFO - /Users/cltbld/tasks/task_1556242733/build/tests/xpcshell/head.js:_execute_test:529
02:27:31 INFO - -e:null:1
02:27:31 INFO - exiting test

Since owner is in PTO and does not accept NI, based on https://wiki.mozilla.org/Modules/All, Dragana could you please take a look?

Flags: needinfo?(dd.mozilla)
Whiteboard: [necko-backlog] → [necko-backlog][stockwell needswork:owner]
Keywords: leave-open
Whiteboard: [necko-backlog][stockwell needswork:owner] → [necko-backlog][stockwell disabled]
Pushed by csabou@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/c59f54df2a00 Disable test_socks.js on mac debug for frequent failures. r=jmaher

I will leave need-info. I have look at this test some time ago and could not figure out what is wrong. I will look at it again.

as a note, this fails on osx 10.14 (only runs in opt, so I assume just opt, but it could fail in both opt/debug) - we will be migrating to osx 10.14

Blocks: 1530474
Status: REOPENED → RESOLVED
Closed: 10 years ago5 years ago
Flags: needinfo?(dd.mozilla)
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: