[B2G] Following tests don't work after raising an exception

RESOLVED WORKSFORME

Status

Testing
Marionette
RESOLVED WORKSFORME
6 years ago
4 years ago

People

(Reporter: zac, Unassigned)

Tracking

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [runner])

(Reporter)

Description

6 years ago
In my test I am raising a Python exception to terminate a test if it is taking too long.

After that successive tests fail at the unlock step.

The trace is:

Traceback (most recent call last):
  File "/home/zacdev/Mozilla/gaia-ui-tests/gaiatest/tests/test_sms.py", line 30, in test_sms_send
    self.assertTrue(self.lockscreen.unlock())
  File "/home/zacdev/Mozilla/gaia-ui-tests/gaiatest/gaia_test.py", line 37, in unlock
    """)
  File "/home/zacdev/.virtualenvs/gaia-ui-tests/local/lib/python2.7/site-packages/marionette_client-0.4-py2.7.egg/marionette/marionette.py", line 391, in execute_async_script
    specialPowers=special_powers)
  File "/home/zacdev/.virtualenvs/gaia-ui-tests/local/lib/python2.7/site-packages/marionette_client-0.4-py2.7.egg/marionette/marionette.py", line 169, in _send_message
    self._handle_error(response)
  File "/home/zacdev/.virtualenvs/gaia-ui-tests/local/lib/python2.7/site-packages/marionette_client-0.4-py2.7.egg/marionette/marionette.py", line 204, in _handle_error
    raise JavascriptException(message=message, status=status, stacktrace=stacktrace)
TEST-UNEXPECTED-FAIL : JavascriptException: TypeError: window.wrappedJSObject.SettingsListener is undefined
START LOG:
(Reporter)

Updated

6 years ago
Summary: [B2G] Phone unusable after raising exception → [B2G] Following tests don't work after raising an exception
(Reporter)

Comment 1

6 years ago
Commenting out the step (line 30 above) causes the test run to just hangs on the next marionette command before eventually a socket timeout:


Traceback (most recent call last):
  File "/home/zacdev/Mozilla/gaia-ui-tests/gaiatest/gaia_test.py", line 76, in setUp
    MarionetteTestCase.setUp(self)
  File "/home/zacdev/.virtualenvs/gaia-ui-tests/local/lib/python2.7/site-packages/marionette_client-0.4-py2.7.egg/marionette/marionette_test.py", line 117, in setUp
    (self.filepath.replace('\\', '\\\\'), self.methodName))
  File "/home/zacdev/.virtualenvs/gaia-ui-tests/local/lib/python2.7/site-packages/marionette_client-0.4-py2.7.egg/marionette/marionette.py", line 379, in execute_script
    specialPowers=special_powers)
  File "/home/zacdev/.virtualenvs/gaia-ui-tests/local/lib/python2.7/site-packages/marionette_client-0.4-py2.7.egg/marionette/marionette.py", line 159, in _send_message
    raise TimeoutException(message='socket.timeout', status=ErrorCodes.TIMEOUT, stacktrace=None)
TEST-UNEXPECTED-FAIL : TimeoutException: socket.timeout
I asked Zac to logcat the output when running and he gave me 

I/Gecko   (  105): MARIONETTE LOG: INFO: TEST-START: /home/zacdev/Mozilla/gaia-ui-tests/gaiatest/tests/test_sms.py:test_sms_send
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:307200 offset:1048576 fd:188
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4be4b000 size:8192 offset:307200 fd:126
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4be9a000 size:8192 offset:630784 fd:147
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4be4d000 size:8192 offset:315392 fd:131
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4be9c000 size:8192 offset:638976 fd:152
W/AudioFlinger(  111): Thread AudioOut_1 cannot connect to the power manager service
I/IdleService(  105): Remove idle observer 48985c80 (1 seconds)
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:307200 offset:1355776 fd:131
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:360448 offset:1662976 fd:147
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:20480 offset:2023424 fd:152
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf4b000 size:307200 offset:1355776 fd:131
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf00000 size:307200 offset:1048576 fd:188
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:360448 offset:1048576 fd:131
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:720896 offset:2043904 fd:185
E/AudioHardwareMSM76XXA(  111): Parsing error in AudioFilter.csv.
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:20480 offset:1409024 fd:190
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf00000 size:360448 offset:1048576 fd:131
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf96000 size:360448 offset:1662976 fd:147
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:720896 offset:2764800 fd:129
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:1187840 offset:3485696 fd:135
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4c0a3000 size:720896 offset:2764800 fd:129
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bff3000 size:720896 offset:2043904 fd:185
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4c153000 size:1187840 offset:3485696 fd:135
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf58000 size:20480 offset:1409024 fd:190
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bfee000 size:20480 offset:2023424 fd:152
I/Gecko   (  105): ###################################### forms.js loaded
I/Gecko   (  105): ###################################### forms.js loaded
E/GeckoConsole(  105): Content JS INFO at app://system.gaiamobile.org/js/window_manager.js:804 in createFrame: %%%%% Launching Messages as local
E/GeckoConsole(  105): Content JS LOG at app://system.gaiamobile.org/js/window_manager.js:379 in anonymous: Window Manager: No screenshot in database. This is expected from a fresh installed app.
E/GeckoConsole(  105): [JavaScript Warning: "Unknown property 'box-sizing'.  Declaration dropped." {file: "app://sms.gaiamobile.org/style/common.css" line: 31}]
E/GeckoConsole(  105): [JavaScript Warning: "CSP WARN:  Directive script-src app://sms.gaiamobile.org violated by http://gaiamobile.org/webapps.js
E/GeckoConsole(  105): "]
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:307200 offset:1048576 fd:129
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:307200 offset:1355776 fd:105
E/GeckoConsole(  105): GC(T+115.6) Total Time: 194.7ms, Compartments Collected: 124, Total Compartments: 125, MMU (20ms): 0%, MMU (50ms): 0%, SCC Sweep Total: 43.5ms, SCC Sweep Max Pause: 20.6ms, Max Pause: 66.0ms, Allocated: 12MB, +Chunks: 3, -Chunks: 0
E/GeckoConsole(  105):     Slice: 0, Pause: 31.0 (When: 0.0ms, Reason: MAYBEGC): Purge: 0.3ms, Mark: 26.5ms, Mark Discard Code: 3.4ms, Mark Roots: 8.2ms
E/GeckoConsole(  105):     Slice: 3, Pause: 66.0 (When: 940.6ms, Reason: REFRESH_FRAME): Mark: 12.4ms, Mark Delayed: 0.2ms, Mark Weak: 0.2ms, Mark Gray: 11.5ms, Mark Gray and Weak: 0.2ms, Finalize Start Callback: 0.7ms, Sweep: 51.3ms, Sweep Compartments: 24.8ms, Sweep Tables: 10.7ms, Sweep Object: 15.8ms, Sweep String: 0.9ms, Sweep Script: 0.9ms, Sweep Shape: 0.2ms, Sweep Discard Code: 2.3ms, Discard Analysis: 10.8ms, Discard TI: 4.2ms, Free TI Arena: 0.2ms, Sweep Types: 4.3ms, Clear Script Analysis: 1.3ms, Finalize End Callback: 4.6ms
E/GeckoConsole(  105):     Slice: 6, Pause: 6.2 (When: 1218.1ms, Reason: REFRESH_FRAME): Sweep: 0.3ms, Deallocate: 0.2ms
E/GeckoConsole(  105):     Totals: Purge: 0.3ms, Mark: 111.0ms, Mar
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:16384 offset:307200 fd:126
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:16384 offset:630784 fd:149
E/GeckoConsole(  105): CC(T+115.9) duration: 43ms, suspected: 941, visited: 1488 RCed and 1436 GCed, collected: 86 RCed and 300 GCed (386 waiting for GC)
E/GeckoConsole(  105): ForgetSkippable 18 times before CC, min: 1 ms, max: 22 ms, avg: 3 ms, total: 58 ms, removed: 2480
E/AudioHardwareMSM76XXA(  111): Parsing error in AudioFilter.csv.
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:16384 offset:1662976 fd:186
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:16384 offset:1679360 fd:191
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:614400 offset:1695744 fd:196
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4be9a000 size:16384 offset:630784 fd:149
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4be4b000 size:16384 offset:307200 fd:126
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf96000 size:16384 offset:1662976 fd:186
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf9a000 size:16384 offset:1679360 fd:191
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:614400 offset:2310144 fd:126
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:675840 offset:2924544 fd:156
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4c034000 size:614400 offset:2310144 fd:126
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf9e000 size:614400 offset:1695744 fd:196
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:675840 offset:1662976 fd:126
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf96000 size:675840 offset:1662976 fd:126
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4c0ca000 size:675840 offset:2924544 fd:156
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:184320 offset:1662976 fd:126
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:184320 offset:1847296 fd:154
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:286720 offset:2031616 fd:186
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:286720 offset:2318336 fd:191
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf96000 size:184320 offset:1662976 fd:126
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bfc3000 size:184320 offset:1847296 fd:154
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:204800 offset:1662976 fd:126
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bff0000 size:286720 offset:2031616 fd:186
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4c036000 size:286720 offset:2318336 fd:191
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:204800 offset:1867776 fd:154
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bfc8000 size:204800 offset:1867776 fd:154
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf96000 size:204800 offset:1662976 fd:126
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:614400 offset:1662976 fd:126
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:614400 offset:2277376 fd:154
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:675840 offset:2891776 fd:186
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4c02c000 size:614400 offset:2277376 fd:154
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf96000 size:614400 offset:1662976 fd:126
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:675840 offset:1662976 fd:126
E/GeckoConsole(  105): GC(T+120.2) Total Time: 174.2ms, Compartments Collected: 125, Total Compartments: 125, MMU (20ms): 0%, MMU (50ms): 0%, SCC Sweep Total: 29.4ms, SCC Sweep Max Pause: 11.8ms, Max Pause: 48.2ms, Allocated: 13MB, +Chunks: 0, -Chunks: 0
E/GeckoConsole(  105):     Slice: 0, Pause: 31.8 (When: 0.0ms, Reason: CC_WAITING): Purge: 0.2ms, Mark: 26.6ms, Mark Discard Code: 3.4ms, Mark Roots: 8.3ms
E/GeckoConsole(  105):     Slice: 4, Pause: 48.2 (When: 183.6ms, Reason: REFRESH_FRAME): Mark: 11.0ms, Mark Weak: 0.2ms, Mark Gray: 10.4ms, Mark Gray and Weak: 0.2ms, Finalize Start Callback: 0.6ms, Sweep: 35.6ms, Sweep Compartments: 18.5ms, Sweep Tables: 7.3ms, Sweep Object: 7.9ms, Sweep String: 1.0ms, Sweep Script: 0.9ms, Sweep Shape: 0.2ms, Sweep Discard Code: 2.4ms, Discard Analysis: 7.8ms, Discard TI: 0.8ms, Free TI Arena: 0.2ms, Sweep Types: 4.7ms, Clear Script Analysis: 1.4ms, Finalize End Callback: 3.5ms
E/GeckoConsole(  105):     Slice: 7, Pause: 4.9 (When: 265.7ms, Reason: REFRESH_FRAME): Sweep: 0.3ms, Deallocate: 0.2ms
E/GeckoConsole(  105):     Totals: Purge: 0.2ms, Mark: 108.8ms, Mark Discard Code: 3.4ms,
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4c0c2000 size:675840 offset:2891776 fd:186
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf96000 size:675840 offset:1662976 fd:126
E/GeckoConsole(  105): CC(T+120.6) duration: 39ms, suspected: 965, visited: 1451 RCed and 1944 GCed, collected: 99 RCed and 133 GCed (232 waiting for GC)
E/GeckoConsole(  105): ForgetSkippable 7 times before CC, min: 1 ms, max: 16 ms, avg: 3 ms, total: 27 ms, removed: 2109
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: bc, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: bc
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: bc
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: bd, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: bd
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: bd
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: be, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: be
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: be
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: c0, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: c0
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: c0
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: c1, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: c1
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: c1
I/ONCRPC  (  109): Setup RPC Call for task 40157420
I/ONCRPC  (  109): oncrpc_xdr_call_msg_start: Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Sent Xid: d5, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Received Reply Xid: d5, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: c2, Prog: 31000000, Vers: fc37ad5c, Proc: 00000004
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: c2
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: c2
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: c3, Prog: 31000000, Vers: fc37ad5c, Proc: 0000000f
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: c3
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: c3
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: c6, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: c6
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: c6
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: c7, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: c7
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: c7
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: c8, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: c8
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: c8
I/ONCRPC  (  109): Setup RPC Call for task 40157420
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: c9, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: c9
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: c9
I/ONCRPC  (  109): oncrpc_xdr_call_msg_start: Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Sent Xid: d6, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Received Reply Xid: d6, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: ca, Prog: 31000000, Vers: fc37ad5c, Proc: 00000004
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: ca
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: ca
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: cb, Prog: 31000000, Vers: fc37ad5c, Proc: 0000000f
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: cb
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: cb
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: cc, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: cc
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: cc
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: cd, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: cd
I/ONCRPC  (  109): Setup RPC Call for task 40157420
I/ONCRPC  (  109): oncrpc_xdr_call_msg_start: Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Sent Xid: d7, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: cd
I/ONCRPC  (  109): xdr_std_msg_send_call: Received Reply Xid: d7, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: ce, Prog: 31000000, Vers: fc37ad5c, Proc: 00000004
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: ce
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: ce
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: cf, Prog: 31000000, Vers: fc37ad5c, Proc: 0000000f
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: cf
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: cf
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: d0, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: d0
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: d0
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: d2, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: d2
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: d2
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: d7, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: d7
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: d7
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: d9, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: d9
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: d9
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: da, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: da
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: da
I/ONCRPC  (  109): Setup RPC Call for task 40157420
I/ONCRPC  (  109): oncrpc_xdr_call_msg_start: Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Sent Xid: d8, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Received Reply Xid: d8, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: db, Prog: 31000000, Vers: fc37ad5c, Proc: 00000004
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: db
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: db
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: dc, Prog: 31000000, Vers: fc37ad5c, Proc: 0000000f
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: dc
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: dc
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: dd, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: dd
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: dd
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: e4, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: e4
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: e4
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: e6, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: e6
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: e6
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: ed, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: ed
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: ed
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: ef, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: ef
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: ef
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: f6, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: f6
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: f6
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: f8, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: f8
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: f8
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: fb, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: fb
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: fb
I/ONCRPC  (  109): Setup RPC Call for task 40157420
I/ONCRPC  (  109): oncrpc_xdr_call_msg_start: Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Sent Xid: d9, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Received Reply Xid: d9, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: fc, Prog: 31000000, Vers: fc37ad5c, Proc: 00000004
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: fc
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: fc
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: fd, Prog: 31000000, Vers: fc37ad5c, Proc: 0000000f
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: fd
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: fd
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: fe, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: fe
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: fe
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: ff, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: ff
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: ff
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 100, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 100
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 100
I/ONCRPC  (  109): Setup RPC Call for task 40157420
I/ONCRPC  (  109): oncrpc_xdr_call_msg_start: Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Sent Xid: da, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Received Reply Xid: da, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 101, Prog: 31000000, Vers: fc37ad5c, Proc: 00000004
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 101
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 101
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 102, Prog: 31000000, Vers: fc37ad5c, Proc: 0000000f
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 102
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 102
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 104, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 104
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 104
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 105, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 105
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 105
E/GeckoConsole(  248): CC(T+164.7) duration: 3ms, suspected: 15, visited: 188 RCed and 44 GCed, collected: 0 RCed and 0 GCed (34 waiting for GC)
E/GeckoConsole(  248): ForgetSkippable 2 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 1 ms, removed: 154
E/GeckoConsole(  105): CC(T+164.7) duration: 3ms, suspected: 15, visited: 188 RCed and 44 GCed, collected: 0 RCed and 0 GCed (34 waiting for GC)
E/GeckoConsole(  105): ForgetSkippable 2 times before CC, min: 0 ms, max: 0 ms, avg: 0 ms, total: 1 ms, removed: 154
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 10a, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 10a
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 10a
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 10d, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 10d
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 10d
I/ONCRPC  (  109): Setup RPC Call for task 40157420
I/ONCRPC  (  109): oncrpc_xdr_call_msg_start: Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Sent Xid: db, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Received Reply Xid: db, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 10e, Prog: 31000000, Vers: fc37ad5c, Proc: 00000004
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 10e
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 10e
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 10f, Prog: 31000000, Vers: fc37ad5c, Proc: 0000000f
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 10f
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 10f
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 111, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 111
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 111
I/ONCRPC  (  109): Setup RPC Call for task 40157420
I/ONCRPC  (  109): oncrpc_xdr_call_msg_start: Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Sent Xid: dc, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): xdr_std_msg_send_call: Received Reply Xid: dc, Prog: 30000000, Ver: ddc9bd91, Proc: 000000b0
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 112, Prog: 31000000, Vers: fc37ad5c, Proc: 00000004
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 112
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 112
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 113, Prog: 31000000, Vers: fc37ad5c, Proc: 0000000f
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 113
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 113
I/ONCRPC  (  109): Setup RPC Call for task 40157420
I/ONCRPC  (  109): oncrpc_xdr_call_msg_start: Prog: 30000003, Ver: febcbbaf, Proc: 00000058
I/ONCRPC  (  109): xdr_std_msg_send_call: Sent Xid: dd, Prog: 30000003, Ver: febcbbaf, Proc: 00000058
I/ONCRPC  (  109): xdr_std_msg_send_call: Received Reply Xid: dd, Prog: 30000003, Ver: febcbbaf, Proc: 00000058
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 114, Prog: 31000003, Vers: cf0d42a3, Proc: 00000001
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 114
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 114
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 115, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 115
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 115
I/ONCRPC  (  109): Setup RPC Call for task 401573d8
I/ONCRPC  (  109): oncrpc_xdr_call_msg_start: Prog: 30000003, Ver: febcbbaf, Proc: 00000069
I/ONCRPC  (  109): xdr_std_msg_send_call: Sent Xid: de, Prog: 30000003, Ver: febcbbaf, Proc: 00000069
I/ONCRPC  (  109): xdr_std_msg_send_call: Received Reply Xid: de, Prog: 30000003, Ver: febcbbaf, Proc: 00000069
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 116, Prog: 31000003, Vers: cf0d42a3, Proc: 00000004
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 116
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 116
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 117, Prog: 31000003, Vers: cf0d42a3, Proc: 00000001
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 117
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 117
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 118, Prog: 31000003, Vers: cf0d42a3, Proc: 00000004
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 118
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 118
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 119, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 119
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 119
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 12a, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 12a
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 12a
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 130, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 130
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 130
I/Gecko   (  105): MARIONETTE LOG: INFO: TEST-END: /home/zacdev/Mozilla/gaia-ui-tests/gaiatest/tests/test_sms.py:test_sms_send
E/GeckoConsole(  105): [JavaScript Error: "[Exception... "Component returned failure code: 0x80470002 (NS_BASE_STREAM_CLOSED) [nsIOutputStream.write]"  nsresult: "0x80470002 (NS_BASE_STREAM_CLOSED)"  location: "JS frame :: chrome://global/content/devtools/dbg-transport.js :: DT_onOutputStreamReady :: line 94"  data: no]" {file: "chrome://global/content/devtools/dbg-transport.js" line: 94}]
E/GeckoConsole(  105): CC(T+246.6) duration: 18ms, suspected: 54, visited: 1158 RCed and 1775 GCed, collected: 0 RCed and 0 GCed (232 waiting for GC)
E/GeckoConsole(  105): ForgetSkippable 15 times before CC, min: 0 ms, max: 2 ms, avg: 1 ms, total: 20 ms, removed: 1488
I/IdleService(  105): next timeout 1350049912764211 usec (300000 msec from now)
I/IdleService(  105): SetTimerExpiryIfBefore: next timeout 1350049912764211 usec
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:307200 offset:1662976 fd:131
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:307200 offset:1970176 fd:155
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf00000 size:307200 offset:1048576 fd:129
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf4b000 size:307200 offset:1355776 fd:105
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf96000 size:307200 offset:1662976 fd:131
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bfe1000 size:307200 offset:1970176 fd:155
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:614400 offset:1048576 fd:105
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:614400 offset:1662976 fd:132
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 14f, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 14f
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 14f
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:245760 offset:2277376 fd:148
D/memalloc(  105): /dev/pmem: Allocated buffer base:0x4be00000 size:245760 offset:2523136 fd:155
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4c068000 size:245760 offset:2523136 fd:155
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4c02c000 size:245760 offset:2277376 fd:148
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf96000 size:614400 offset:1662976 fd:132
D/memalloc(  105): /dev/pmem: Freeing buffer base:0x4bf00000 size:614400 offset:1048576 fd:105
E/GeckoConsole(  105): GC(T+296.0) Total Time: 166.7ms, Compartments Collected: 124, Total Compartments: 124, MMU (20ms): 0%, MMU (50ms): 8%, SCC Sweep Total: 26.9ms, SCC Sweep Max Pause: 3.5ms, Max Pause: 45.6ms, Allocated: 13MB, +Chunks: 0, -Chunks: 0
E/GeckoConsole(  105):     Slice: 0, Pause: 31.0 (When: 0.0ms, Reason: PAGE_HIDE): Purge: 0.1ms, Mark: 27.4ms, Mark Discard Code: 2.7ms, Mark Roots: 8.0ms
E/GeckoConsole(  105):     Slice: 3, Pause: 45.6 (When: 396.0ms, Reason: INTER_SLICE_GC): Mark: 11.4ms, Mark Weak: 0.2ms, Mark Gray: 11.0ms, Mark Gray and Weak: 0.2ms, Finalize Start Callback: 0.6ms, Sweep: 32.4ms, Sweep Compartments: 17.5ms, Sweep Tables: 7.7ms, Sweep Object: 6.6ms, Sweep String: 0.9ms, Sweep Script: 0.8ms, Sweep Shape: 0.2ms, Sweep Discard Code: 2.0ms, Discard Analysis: 6.8ms, Discard TI: 1.3ms, Free TI Arena: 0.2ms, Sweep Types: 3.2ms, Clear Script Analysis: 1.6ms, Finalize End Callback: 2.8ms
E/GeckoConsole(  105):     Slice: 6, Pause: 6.4 (When: 751.4ms, Reason: INTER_SLICE_GC): Sweep: 0.2ms, Deallocate: 0.2ms
E/GeckoConsole(  105):     Totals: Purge: 0.1ms, Mark: 106.4ms, Mark Discard Code: 2.7ms,
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 156, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 156
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 156
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 158, Prog: 31000000, Vers: fc37ad5c, Proc: 00000012
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 158
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 158
E/GeckoConsole(  105): CC(T+302.0) duration: 19ms, suspected: 108, visited: 1249 RCed and 1779 GCed, collected: 70 RCed and 0 GCed (70 waiting for GC)
E/GeckoConsole(  105): ForgetSkippable 6 times before CC, min: 0 ms, max: 16 ms, avg: 5 ms, total: 32 ms, removed: 1165
E/GeckoConsole(  105): [JavaScript Error: "can't access dead object" {file: "chrome://marionette/content/marionette-listener.js" line: 253}]
I/IdleService(  105): Get idle time: time since reset 121890 msec
I/IdleService(  105): Idle timer callback: current idle time 121890 msec
I/IdleService(  105): next timeout 1350049918050313 usec (178109 msec from now)
I/IdleService(  105): SetTimerExpiryIfBefore: next timeout 1350049918050313 usec
I/IdleService(  105): reset timer expiry from 0 usec to 1350049918060313 usec
E/GeckoConsole(  105): CC(T+428.0) duration: 16ms, suspected: 33, visited: 1096 RCed and 1779 GCed, collected: 0 RCed and 0 GCed (70 waiting for GC)
E/GeckoConsole(  105): ForgetSkippable 6 times before CC, min: 0 ms, max: 1 ms, avg: 0 ms, total: 5 ms, removed: 922
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 1bf, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 1bf
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 1bf
I/ONCRPC  (  109): rpc_handle_rpc_call: for Xid: 1c5, Prog: 31000003, Vers: cf0d42a3, Proc: 00000003
I/ONCRPC  (  109): rpc_handle_rpc_call: Find Status: 0 Xid: 1c5
I/ONCRPC  (  109): oncrpc_proxy_handle_cmd_rpc_call: Dispatching xid: 1c5
E/GeckoConsole(  105): [JavaScript Error: "[Exception... "Component returned failure code: 0x80470002 (NS_BASE_STREAM_CLOSED) [nsIOutputStream.write]"  nsresult: "0x80470002 (NS_BASE_STREAM_CLOSED)"  location: "JS frame :: chrome://global/content/devtools/dbg-transport.js :: DT_onOutputStreamReady :: line 94"  data: no]" {file: "chrome://global/content/devtools/dbg-transport.js" line: 94}]
I/IdleService(  105): Get idle time: time since reset 300009 msec
I/IdleService(  105): Idle timer callback: current idle time 300009 msec
I/IdleService(  105): next timeout 5645016913050313 usec (4294966994990 msec from now)
I/IdleService(  105): SetTimerExpiryIfBefore: next timeout 5645016913050313 usec
I/IdleService(  105): reset timer expiry from 0 usec to 5645016913060313 usec
I/IdleService(  105): Idle timer callback: tell observer 4a6f8c80 user is idle
I/IdleService(  105): Notifying idle-daily observers
I/IdleService(  105): Remove idle observer 4a6f8c80 (300 seconds)
I/IdleService(  105): Storing last idle time as 1350049918
From the logcat, the item that stands out is 

E/GeckoConsole(  105): [JavaScript Error: "can't access dead object" {file: "chrome://marionette/content/marionette-listener.js" line: 253}]
Can you attach the test case that's triggering this behavior?
(Reporter)

Comment 5

6 years ago
I am just about to leave the office but try this:
raise Exception('kill')

into test_calculator.py, somewhere after the app has started up and see if that hangs it.

Then after that fails immediately run the test again.
(In reply to Zac C from comment #5)
> I am just about to leave the office but try this:
> raise Exception('kill')
> 
> into test_calculator.py, somewhere after the app has started up and see if
> that hangs it.
> 
> Then after that fails immediately run the test again.

This comment makes me think what's happening is that we're not setting up good initial state in newSession, which would be a problem if the last test session didn't get cleaned up correctly.
(Reporter)

Comment 7

6 years ago
:jgriffin I just stumbled upon bug 748110 which sounds similar.
(In reply to Zac C from comment #7)
> :jgriffin I just stumbled upon bug 748110 which sounds similar.

Yes, these are likely the same bug.
Duplicate of this bug: 748110
I tried adding an exception to test_calculator.py, and running it (letting it fail), then running test_kill_marketplace.py (from bug 802136) and it worked fine.

I also tried running the test several times in quick succession, and didn't see the error.

If this problem still occurs, please attach a test for it and I'll take another look.
Status: NEW → RESOLVED
Last Resolved: 6 years ago
Resolution: --- → WORKSFORME
(Reporter)

Comment 11

6 years ago
I think this is one of the tests that was improved by moving the Marionette teardown into the test rather than the suite (thus creating a new session for each test).
(Reporter)

Comment 12

6 years ago
Jonathan I retract my last comment.

I just looked at bug 748110 and by your own comment there you know exactly how to replicate this.

The problem here with regard to a CI is not Marionette crashing and not closing the socket. The problem is what to do when the 2nd test starts up and finds the socket open/locked. Marionette or the framework needs to handle that.
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
I think this can't happen with the current Marionette Python testrunner, since it closes the socket (and thus the session) after any kind of error.  Bug 748110 involves the JS Marionette client, which might not be as well-behaved.
Whiteboard: [runner]
(Reporter)

Comment 14

4 years ago
This doesn't occur anymore.
Status: REOPENED → RESOLVED
Last Resolved: 6 years ago4 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.