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>)
Fixed in r20444.
this ticket has been moved to: https://github.com/Xpra-org/xpra/issues/1962