Skip to content

Conversation

@epmog
Copy link
Contributor

@epmog epmog commented Dec 31, 2025

What was the problem/requirement? (What/Why)

Trying to debug some time-senstive tests and why they're failing, but unable to determine when information is being logged without adding it to the message.

What was the solution? (How)

Change the pytest log format

What is the impact of this change?

Here's a time sensitive test that was failing since "Log from test 4" was not in the log messages. before the change, we can't tell why the action that prints every second didn't print the last log message.

Before

INFO     sessions.conftest.tU7r0SS5KK4c4DmLgLagnxvQRFuaMX55:_logging.py:89 ----------------------------------------------
INFO     sessions.conftest.tU7r0SS5KK4c4DmLgLagnxvQRFuaMX55:_logging.py:90 Phase: Running action
INFO     sessions.conftest.tU7r0SS5KK4c4DmLgLagnxvQRFuaMX55:_logging.py:91 ----------------------------------------------
INFO     sessions.conftest.tU7r0SS5KK4c4DmLgLagnxvQRFuaMX55:_subprocess.py:297 Running command /private/var/folders/j_/kh9hgnt51jn_4rk3z3dz6m_h0000gr/T/pytest-of-morgane/pytest-47/popen-gw5/test_run_action_default_timeou0/tmpx775326c.sh
INFO     sessions.conftest.tU7r0SS5KK4c4DmLgLagnxvQRFuaMX55:_subprocess.py:188 Command started as pid: 72099
INFO     sessions.conftest.tU7r0SS5KK4c4DmLgLagnxvQRFuaMX55:_subprocess.py:192 Output:
INFO     sessions.conftest.tU7r0SS5KK4c4DmLgLagnxvQRFuaMX55:_subprocess.py:401 Log from test 0
INFO     sessions.conftest.tU7r0SS5KK4c4DmLgLagnxvQRFuaMX55:_subprocess.py:401 Log from test 1
INFO     sessions.conftest.tU7r0SS5KK4c4DmLgLagnxvQRFuaMX55:_subprocess.py:401 Log from test 2
INFO     sessions.conftest.tU7r0SS5KK4c4DmLgLagnxvQRFuaMX55:_runner_base.py:615 TIMEOUT - Runtime limit reached at 2025-12-31T18:09:33Z. Canceling action.
INFO     sessions.conftest.tU7r0SS5KK4c4DmLgLagnxvQRFuaMX55:_runner_base.py:494 Canceling subprocess 72099 via termination method at 2025-12-31T18:09:33Z.
INFO     sessions.conftest.tU7r0SS5KK4c4DmLgLagnxvQRFuaMX55:_subprocess.py:540 INTERRUPT: Sending signal "kill" to process group 72099
INFO     sessions.conftest.tU7r0SS5KK4c4DmLgLagnxvQRFuaMX55:_subprocess.py:441 Process pid 72099 exited with code: -9 (unsigned) / -0x9 (hex)

After

12:03:02.548 INFO          _logging.py:89  ----------------------------------------------
12:03:02.548 INFO          _logging.py:90  Phase: Running action
12:03:02.548 INFO          _logging.py:91  ----------------------------------------------
12:03:02.548 INFO       _subprocess.py:297 Running command /private/var/folders/j_/kh9hgnt51jn_4rk3z3dz6m_h0000gr/T/pytest-of-morgane/pytest-46/popen-gw7/test_run_action_default_timeou0/tmpzyw8e6jm.sh
12:03:02.551 INFO       _subprocess.py:188 Command started as pid: 69897
12:03:02.551 INFO       _subprocess.py:192 Output:
12:03:05.062 INFO       _subprocess.py:401 Log from test 0
12:03:06.066 INFO       _subprocess.py:401 Log from test 1
12:03:07.070 INFO       _subprocess.py:401 Log from test 2
12:03:07.553 INFO      _runner_base.py:615 TIMEOUT - Runtime limit reached at 2025-12-31T18:03:07Z. Canceling action.
12:03:07.553 INFO      _runner_base.py:494 Canceling subprocess 69897 via termination method at 2025-12-31T18:03:07Z.
12:03:07.553 INFO       _subprocess.py:540 INTERRUPT: Sending signal "kill" to process group 69897
12:03:07.554 INFO       _subprocess.py:441 Process pid 69897 exited with code: -9 (unsigned) / -0x9 (hex)

With the new logging, we can see that it's taking longer than 1 second from Output: to the first log we receive. We're asserting that timeout - 1 appears in the logs, which will fail if it takes longer than 1 second to start printing.

How was this change tested?

hatch run test

Was this change documented?

N/A

Is this a breaking change?

N/A

Does this change impact security?

N/A


By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

@epmog epmog requested a review from a team as a code owner December 31, 2025 18:07
@epmog epmog enabled auto-merge (squash) December 31, 2025 18:11
@epmog epmog force-pushed the format_test_logging branch from 2b11cf9 to 060f43a Compare December 31, 2025 18:12
@epmog epmog force-pushed the format_test_logging branch from 060f43a to 27425da Compare December 31, 2025 19:56
@sonarqubecloud
Copy link

@epmog epmog merged commit 48fdc35 into OpenJobDescription:mainline Dec 31, 2025
25 checks passed
@epmog epmog deleted the format_test_logging branch December 31, 2025 20:01
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants