search

ionelmc / python-hunter

Hunter is a flexible code tracing toolkit.
https://python-hunter.readthedocs.io/
BSD 2-Clause "Simplified" License
794 stars 46 forks source link

test failures #100

Open Alessandro-Barbieri opened 3 years ago

Alessandro-Barbieri commented 3 years ago

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

ionelmc commented 3 years ago

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?

guettli commented 3 years ago

@Alessandro-Barbieri the issue is closed in gentoo. Maybe you want to close this issue, too?

Alessandro-Barbieri commented 3 years ago

@Alessandro-Barbieri the issue is closed in gentoo. Maybe you want to close this issue, too?

No, I've only deselected the failing tests

abitrolly commented 2 years ago

@Alessandro-Barbieri does that mean manhole is broken in Gentoo?