python-hunter
python-hunter copied to clipboard
ionelmc
test failures
While packaging this for gentoo overlay guru I got the errors below:
=================================== FAILURES ===================================
_________________________________ test_manhole _________________________________
tests/test_remote.py:29: in test_manhole
wait_for_strings(target.read, TIMEOUT, 'Broken pipe', 'Stopping tracer.')
target = TestProcess(pid=96, is_alive=False)
tracer = TestProcess(pid=100, is_alive=False)
/usr/lib/python3.8/site-packages/process_tests.py:247: in wait_for_strings
raise AssertionError("Waited %0.2fsecs but %s did not appear in output in the given order !" % (
E AssertionError: Waited 10.00secs but ['Stopping tracer.', 'Broken pipe'] did not appear in output in the given order !
buff = ('Manhole[96:1624881702.5855]: Not patching os.fork and os.forkpty. Oneshot '
'activation is done by signal Signals.SIGURG\n'
'Manhole[96:1624881702.7540]: Manhole UDS path: /tmp/manhole-96\n'
'Manhole[96:1624881702.7540]: Waiting for new connection (in pid:96) ...\n'
'Manhole[96:1624881702.7541]: Accepted connection on fd:4 from PID:100 '
'UID:250 GID:250\n'
'Manhole[96:1624881702.7543]: Running: "from hunter import remote; '
"remote.activate('/tmp/hunter-100', False, 'utf-8', "
'\'stdlib=False\')\\n".\n'
"Manhole[96:1624881702.7559]: Running: 'exit()\\n'.\n"
'Manhole[96:1624881702.7573]: Exiting exec loop.\n')
cb = <bound method BufferingBase.read of TestProcess(pid=96, is_alive=False)>
check_strings = ['Stopping tracer.', 'Broken pipe']
line = 'Manhole[96:1624881702.7573]: Exiting exec loop.'
seconds = 10
start = 1624881705.8134274
strings = ('Broken pipe', 'Stopping tracer.')
----------------------------- Captured stdout call -----------------------------
*********** OUTPUT ***********
Manhole[96:1624881702.5855]: Not patching os.fork and os.forkpty. Oneshot activation is done by signal Signals.SIGURG
Manhole[96:1624881702.7540]: Manhole UDS path: /tmp/manhole-96
Manhole[96:1624881702.7540]: Waiting for new connection (in pid:96) ...
Manhole[96:1624881702.7541]: Accepted connection on fd:4 from PID:100 UID:250 GID:250
Manhole[96:1624881702.7543]: Running: "from hunter import remote; remote.activate('/tmp/hunter-100', False, 'utf-8', 'stdlib=False')\n".
Manhole[96:1624881702.7559]: Running: 'exit()\n'.
Manhole[96:1624881702.7573]: Exiting exec loop.
******************************
___________________________ test_manhole_clean_exit ____________________________
tests/test_remote.py:47: in test_manhole_clean_exit
wait_for_strings(target.read, TIMEOUT,
target = TestProcess(pid=104, is_alive=False)
tracer = TestProcess(pid=108, is_alive=False)
/usr/lib/python3.8/site-packages/process_tests.py:247: in wait_for_strings
raise AssertionError("Waited %0.2fsecs but %s did not appear in output in the given order !" % (
E AssertionError: Waited 10.00secs but ['Doing stuff', 'Doing stuff', 'Doing stuff'] did not appear in output in the given order !
buff = ('Manhole[104:1624881717.4568]: Manhole UDS path: /tmp/manhole-104\n'
'Manhole[104:1624881717.4568]: Waiting for new connection (in pid:104) ...\n'
'Manhole[104:1624881717.4570]: Accepted connection on fd:4 from PID:108 '
'UID:250 GID:250\n'
'Manhole[104:1624881717.4572]: Running: "from hunter import remote; '
"remote.activate('/tmp/hunter-108', False, 'utf-8', "
'\'stdlib=False\')\\n".\n'
"Manhole[104:1624881717.4594]: Running: 'exit()\\n'.\n"
'Manhole[104:1624881717.4611]: Exiting exec loop.\n'
'Manhole[104:1624881719.3209]: Manhole UDS path: /tmp/manhole-104\n'
'Manhole[104:1624881719.3216]: Waiting for new connection (in pid:104) ...\n'
'Manhole[104:1624881719.3239]: Accepted connection on fd:4 from PID:108 '
'UID:250 GID:250\n'
"Manhole[104:1624881719.3261]: Running: 'from hunter import remote; "
"remote.deactivate()\\n'.\n"
"Manhole[104:1624881719.3273]: Running: 'exit()\\n'.\n"
'Manhole[104:1624881719.3274]: Exiting exec loop.\n')
cb = <bound method BufferingBase.read of TestProcess(pid=104, is_alive=False)>
check_strings = ['Doing stuff', 'Doing stuff', 'Doing stuff']
line = 'Manhole[104:1624881719.3274]: Exiting exec loop.'
seconds = 10
start = 1624881719.5192776
strings = ('remote.deactivate()', 'Doing stuff', 'Doing stuff', 'Doing stuff')
----------------------------- Captured stdout call -----------------------------
*********** OUTPUT ***********
Manhole[104:1624881717.4568]: Manhole UDS path: /tmp/manhole-104
Manhole[104:1624881717.4568]: Waiting for new connection (in pid:104) ...
Manhole[104:1624881717.4570]: Accepted connection on fd:4 from PID:108 UID:250 GID:250
Manhole[104:1624881717.4572]: Running: "from hunter import remote; remote.activate('/tmp/hunter-108', False, 'utf-8', 'stdlib=False')\n".
Manhole[104:1624881717.4594]: Running: 'exit()\n'.
Manhole[104:1624881717.4611]: Exiting exec loop.
Manhole[104:1624881719.3209]: Manhole UDS path: /tmp/manhole-104
Manhole[104:1624881719.3216]: Waiting for new connection (in pid:104) ...
Manhole[104:1624881719.3239]: Accepted connection on fd:4 from PID:108 UID:250 GID:250
Manhole[104:1624881719.3261]: Running: 'from hunter import remote; remote.deactivate()\n'.
Manhole[104:1624881719.3273]: Running: 'exit()\n'.
Manhole[104:1624881719.3274]: Exiting exec loop.
******************************
------------------------------------------------------------------------------------------------------ benchmark: 6 tests -----------------------------------------------------------------------------------------------------
Name (time in us) Min Max Mean StdDev Median IQR Outliers OPS Rounds Iterations
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
test_probe[no_probe] 15.1298 (1.0) 760.6531 (1.0) 15.3464 (1.0) 3.4970 (1.0) 15.3184 (1.0) 0.0694 (1.0) 53;786 65,161.7396 (1.0) 45619 1
test_probe[fast_probe] 143.9727 (9.52) 929.3230 (1.22) 157.5877 (10.27) 18.7469 (5.36) 161.5318 (10.54) 17.2644 (248.83) 22;10 6,345.6727 (0.10) 4351 1
test_probe[brief_probe] 232.6570 (15.38) 1,041.8324 (1.37) 246.5197 (16.06) 23.2296 (6.64) 237.8458 (15.53) 23.3571 (336.64) 29;11 4,056.4703 (0.06) 3528 1
test_perf_filter[cython] 274,501.9039 (>1000.0) 354,294.5948 (465.78) 304,883.3194 (>1000.0) 32,353.0886 (>1000.0) 301,420.9466 (>1000.0) 47,793.7540 (>1000.0) 1;0 3.2799 (0.00) 5 1
test_perf_actions[cython] 455,421.3379 (>1000.0) 488,003.5832 (641.56) 467,119.1530 (>1000.0) 12,828.7531 (>1000.0) 463,430.7548 (>1000.0) 16,124.5076 (>1000.0) 1;0 2.1408 (0.00) 5 1
test_perf_stdlib[cython] 902,216.5239 (>1000.0) 920,643.3422 (>1000.0) 909,875.8356 (>1000.0) 7,485.2808 (>1000.0) 909,887.4042 (>1000.0) 11,693.8566 (>1000.0) 2;0 1.0991 (0.00) 5 1
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Legend:
Outliers: 1 Standard Deviation from Mean; 1.5 IQR (InterQuartile Range) from 1st Quartile and 3rd Quartile.
OPS: Operations Per Second, computed as 1 / Mean
=========================== short test summary info ============================
SKIPPED [1] tests/test_remote.py:54: condition: not distutils.spawn.find_executable("gdb")
SKIPPED [1] tests/test_remote.py:73: condition: not distutils.spawn.find_executable("gdb")
SKIPPED [3] tests/test_tracer.py:658: <class 'hunter.tracer.Tracer'> is not <class 'hunter._tracer.Tracer'> in this environment
SKIPPED [1] tests/test_tracer.py:1120: condition: not os.environ.get('PUREPYTHONHUNTER')
SKIPPED [1] tests/test_tracer.py:1194: condition: not os.environ.get('PUREPYTHONHUNTER')
SKIPPED [1] tests/test_tracer.py:1323: condition: not os.environ.get('PUREPYTHONHUNTER')
SKIPPED [1] tests/test_tracer.py:1470: condition: PY3
FAILED tests/test_remote.py::test_manhole - AssertionError: Waited 10.00secs ...
FAILED tests/test_remote.py::test_manhole_clean_exit - AssertionError: Waited...
============= 2 failed, 750 passed, 9 skipped in 69.94s (0:01:09) ==============
Traceback (most recent call last):
File "src/hunter/_tracer.pyx", line 49, in hunter._tracer.trace_func
fast_call(handler, event)
File "src/hunter/_predicates.pyx", line 585, in hunter._predicates.fast_call
return fast_When_call(<When> callable, event)
File "src/hunter/_predicates.pyx", line 354, in hunter._predicates.fast_When_call
result = fast_call(self.condition, event)
File "src/hunter/_predicates.pyx", line 591, in hunter._predicates.fast_call
return callable(event)
TypeError: <lambda>() takes 0 positional arguments but 1 was given
Disabling tracer because handler <hunter._predicates.When: condition=<function test_tracer_autostop.<locals>.<lambda> at 0x7fbebed7f550>, actions=(CallPrinter(stream=<_io.TextIOWrapper name='<stderr>' mode='w' encoding='utf-8'>, force_colors=False, filename_alignment=40, thread_alignment=12, pid_alignment=9 repr_limit=1024, repr_func=<function safe_repr at 0x7fbec060c700>),)> failed (TypeError('<lambda>() takes 0 positional arguments but 1 was given')) at <Event kind='return' function='trace' module='hunter' filename='/var/tmp/portage/dev-python/hunter-3.3.8/work/python-hunter-3.3.8-python3_8/lib/hunter/__init__.py' lineno=384>.
[...]ter-3.3.8/tests/test_integration.py:304 line node += 'x'
[...]ython-hunter-3.3.8/tests/sample7.py:27 call => five()
[...]ython-hunter-3.3.8/tests/sample7.py:28 line in_five = 1
[...]ython-hunter-3.3.8/tests/sample7.py:29 line for i in range(1): # five
[...]ython-hunter-3.3.8/tests/sample7.py:30 line return i
[...]ython-hunter-3.3.8/tests/sample7.py:30 return <= five: 0
[...]ython-hunter-3.3.8/tests/sample7.py:27 call => five()
[...]ython-hunter-3.3.8/tests/sample7.py:28 line in_five = 1
[...]ython-hunter-3.3.8/tests/sample7.py:29 line for i in range(1): # five
[...]ython-hunter-3.3.8/tests/sample7.py:30 line return i
[...]ython-hunter-3.3.8/tests/sample7.py:30 return <= five: 0
[...].8-python3_8/lib/hunter/__init__.py:384 return def trace(*predicates, **options):
... return value: <hunter._tracer.Tracer object at 0x7fbebec10e20>
[...]n-hunter-3.3.8/tests/test_tracer.py:635 line def a():
[...]n-hunter-3.3.8/tests/test_tracer.py:638 line a()
[...]n-hunter-3.3.8/tests/test_tracer.py:635 call def a():
[...]n-hunter-3.3.8/tests/test_tracer.py:636 line pass
[...]n-hunter-3.3.8/tests/test_tracer.py:636 return pass
... return value: None
[...]ython-hunter-3.3.8/tests/sample7.py:27 call => five()
[...]ython-hunter-3.3.8/tests/sample7.py:28 line in_five = 1
[...]ython-hunter-3.3.8/tests/sample7.py:29 line for i in range(1): # five
[...]ython-hunter-3.3.8/tests/sample7.py:30 line return i
[...]ython-hunter-3.3.8/tests/sample7.py:30 return <= five: 0
[...]ython-hunter-3.3.8/tests/sample7.py:27 call => five()
[...]ython-hunter-3.3.8/tests/sample7.py:28 line in_five = 1
[...]ython-hunter-3.3.8/tests/sample7.py:29 line for i in range(1): # five
[...]ython-hunter-3.3.8/tests/sample7.py:30 line return i
[...]ython-hunter-3.3.8/tests/sample7.py:30 return <= five: 0
* ERROR: dev-python/hunter-3.3.8::guru failed (test phase):
* pytest failed with python3.8
Full log here: https://799026.bugs.gentoo.org/attachment.cgi?id=719727 https://bugs.gentoo.org/799026
Well it would appear that for those tests the tracing works but the target process is hosed (AssertionError: Waited 10.00secs but ['Doing stuff', 'Doing stuff', 'Doing stuff'] did not appear in output in the given order !). IOW the process doesn't resume normally and output Doing stuff after the tracer de-attaches. Well actually ... I'm not sure if the process works normally anyway since I don't have any assertion of that about before tracer attaches. Is there an easy way I can reproduce the problem you had there - like a docker container thing to run your build system?
@Alessandro-Barbieri the issue is closed in gentoo. Maybe you want to close this issue, too?
@Alessandro-Barbieri the issue is closed in gentoo. Maybe you want to close this issue, too?
No, I've only deselected the failing tests
