Xpra: Ticket #1962: subprocess_wrapper_test can fail - under load?

With full debug:

$ XPRA_ALL_DEBUG=1 PYTHONPATH=.. python2 ./unit/net/subprocess_wrapper_test.py
2018-09-18 18:01:49,934 packet_encoding.init_rencode() has_rencode=True, use_rencode=True, version=('Cython', 1, 0, 5)
2018-09-18 18:01:49,934 Warning: cannot load cython bencode module: No module named cython_bencode
2018-09-18 18:01:49,934 packet_encoding.init_bencode() has_bencode=True, use_bencode=True, version=('Python', 0, 11)
2018-09-18 18:01:49,949 packet encoding: has_yaml=True, use_yaml=True, version=3.12
2018-09-18 18:01:49,949 no accelerated xor
Traceback (most recent call last):
  File "/home/antoine/projects/Xpra/trunk/src/xpra/net/digest.py", line 18, in <module>
    from xpra.codecs.xor.cyxor import xor_str           #@UnresolvedImport
ImportError: No module named cyxor
2018-09-18 18:01:49,949 no accelerated xor
Traceback (most recent call last):
  File "/home/antoine/projects/Xpra/trunk/src/xpra/net/crypto.py", line 42, in <module>
    from xpra.codecs.xor.cyxor import xor_str           #@UnresolvedImport
ImportError: No module named cyxor
2018-09-18 18:01:49,951 connect_export['test-signal']
2018-09-18 18:01:49,951 Connection('fake', 'fake', {})
2018-09-18 18:01:49,951 get_enabled_encoders(['rencode', 'bencode', 'yaml']) enabled=['yaml', 'rencode', 'bencode']
2018-09-18 18:01:49,951 enable_encoder(rencode): <function do_rencode at 0x7f63d61e1f50>
2018-09-18 18:01:49,951 enable_compressor(none): <function nocompress at 0x7f63d64cbc08>
2018-09-18 18:01:49,951 export(test-signal, ...)
2018-09-18 18:01:49,951 send: adding 'test-signal' message (0 items already in queue)
2018-09-18 18:01:49,951 write_format_thread_loop starting
2018-09-18 18:01:49,951 send: adding 'loop_stop' message (1 items already in queue)
2018-09-18 18:01:49,951 add_packet_to_queue(test-signal ... True, False, False)
2018-09-18 18:01:49,952 io_thread_loop(read, <bound method Protocol._read of Protocol(<__main__.loopback_connection object at 0x7f63d52e26d0>)>) loop starting
2018-09-18 18:01:49,952 io_thread_loop(write, <bound method Protocol._write of Protocol(<__main__.loopback_connection object at 0x7f63d52e26d0>)>) loop starting
2018-09-18 18:01:49,952 read_parse_thread_loop starting
2018-09-18 18:01:49,952 processing packet test-signal
2018-09-18 18:01:49,952 test_signal_function('hello foo',)
2018-09-18 18:01:59,961 timeout_error
2018-09-18 18:01:59,961 loop_stop() timeout_fn=None
2018-09-18 18:01:59,961 stop() protocol=Protocol(<__main__.loopback_connection object at 0x7f63d52e26d0>)
2018-09-18 18:01:59,961 Protocol.close() closed=False, connection=<__main__.loopback_connection object at 0x7f63d52e26d0>
2018-09-18 18:01:59,961 Protocol.close() calling <bound method loopback_connection.close of <__main__.loopback_connection object at 0x7f63d52e26d0>>
2018-09-18 18:01:59,961 terminate_queue_threads()
2018-09-18 18:01:59,961 read thread: eof
2018-09-18 18:01:59,961 parse thread: empty marker, exiting
2018-09-18 18:01:59,961 io_thread_loop(read, <bound method Protocol._read of Protocol(None)>) loop ended, closed=True
2018-09-18 18:01:59,962 write thread: empty marker, exiting
2018-09-18 18:01:59,962 Protocol.close() closed=True, connection=None
2018-09-18 18:01:59,962 io_thread_loop(write, <bound method Protocol._write of Protocol(None)>) loop ended, closed=True
2018-09-18 18:01:59,962 Protocol.close() done
2018-09-18 18:01:59,962 stop() stopping mainloop <glib.MainLoop object at 0x7f63d66fa630>
2018-09-18 18:01:59,962 run() ended, calling cleanup and protocol close
2018-09-18 18:01:59,962 connection-lost: [], calling stop
2018-09-18 18:01:59,962 net_stop() will call stop from main thread
2018-09-18 18:01:59,962 Protocol.close() closed=True, connection=None
2018-09-18 18:01:59,962 stop() protocol=None
2018-09-18 18:01:59,962 stop() stopping mainloop <glib.MainLoop object at 0x7f63d66fa630>
2018-09-18 18:01:59,962 readback=[('hello foo',)]
2018-09-18 18:01:59,962 rss=hello foo, timeout=True
(..)
======================================================================
FAIL: test_loopback_callee (__main__.SubprocessWrapperTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "./unit/net/subprocess_wrapper_test.py", line 164, in test_loopback_callee
    assert self.timeout is False, "the test did not exit cleanly (not received the 'end' packet?)"
AssertionError: the test did not exit cleanly (not received the 'end' packet?)
----------------------------------------------------------------------
Ran 2 tests in 10.015s

When the test succeeds the output differs here:

2018-09-18 18:02:00,304 read_parse_thread_loop starting
2018-09-18 18:02:00,304 processing packet test-signal
2018-09-18 18:02:00,304 processing packet loop_stop
2018-09-18 18:02:00,305 test_signal_function('hello foo',)
2018-09-18 18:02:00,305 loop_stop() timeout_fn=3
2018-09-18 18:02:00,305 stop() protocol=Protocol(<__main__.loopback_connection object at 0x7f23ff90f6d0>)


Tue, 18 Sep 2018 11:17:32 GMT - Antoine Martin: status changed; resolution set

Fixed in r20444.


Sat, 23 Jan 2021 05:38:27 GMT - migration script:

this ticket has been moved to: https://github.com/Xpra-org/xpra/issues/1962