Skip to content

Localize test output so it's possible to run specific test#964

Merged
brandur merged 1 commit into
masterfrom
brandur-localize-test-output
Jul 2, 2025
Merged

Localize test output so it's possible to run specific test#964
brandur merged 1 commit into
masterfrom
brandur-localize-test-output

Conversation

@brandur

@brandur brandur commented Jun 28, 2025

Copy link
Copy Markdown
Contributor

This one's aimed at fixing a very long running problem we've had in that
it's impossible to get test output for only one specific test, which
makes debugging extremely difficult/onerous.

Here's a rough demonstration of the problem. I want to run only one test
case and get it's output:

$ go test . -run Test_Client/WithWorkerMiddlewareOnWorker -test.v
=== RUN   Test_Client
=== PAUSE Test_Client
=== RUN   Test_Client_Stop
=== PAUSE Test_Client_Stop
=== RUN   Test_Client_Stop_AfterContextCancelled
=== PAUSE Test_Client_Stop_AfterContextCancelled
=== RUN   Test_Client_StopAndCancel
=== PAUSE Test_Client_StopAndCancel
=== RUN   Test_Client_JobContextInheritsFromProvidedContext
=== PAUSE Test_Client_JobContextInheritsFromProvidedContext
=== RUN   Test_Client_ClientFromContext
=== PAUSE Test_Client_ClientFromContext
=== RUN   Test_Client_JobDelete
=== PAUSE Test_Client_JobDelete
=== RUN   Test_Client_Insert
=== PAUSE Test_Client_Insert
=== RUN   Test_Client_InsertTx
=== PAUSE Test_Client_InsertTx
=== RUN   Test_Client_InsertManyFast
=== PAUSE Test_Client_InsertManyFast
=== RUN   Test_Client_InsertManyFastTx
=== PAUSE Test_Client_InsertManyFastTx
=== RUN   Test_Client_InsertMany
=== PAUSE Test_Client_InsertMany
=== RUN   Test_Client_InsertManyTx
=== PAUSE Test_Client_InsertManyTx
=== RUN   Test_Client_JobGet
=== PAUSE Test_Client_JobGet
=== RUN   Test_Client_JobList
=== PAUSE Test_Client_JobList
=== RUN   Test_Client_JobRetry
=== PAUSE Test_Client_JobRetry
=== RUN   Test_Client_ErrorHandler
=== PAUSE Test_Client_ErrorHandler
=== RUN   Test_Client_Maintenance
=== PAUSE Test_Client_Maintenance
=== RUN   Test_Client_QueueGet
=== PAUSE Test_Client_QueueGet
=== RUN   Test_Client_QueueGetTx
=== PAUSE Test_Client_QueueGetTx
=== RUN   Test_Client_QueueList
=== PAUSE Test_Client_QueueList
=== RUN   Test_Client_QueueListTx
=== PAUSE Test_Client_QueueListTx
=== RUN   Test_Client_RetryPolicy
=== PAUSE Test_Client_RetryPolicy
=== RUN   Test_Client_Subscribe
=== PAUSE Test_Client_Subscribe
=== RUN   Test_Client_SubscribeConfig
=== PAUSE Test_Client_SubscribeConfig
=== RUN   Test_Client_InsertTriggersImmediateWork
=== PAUSE Test_Client_InsertTriggersImmediateWork
=== RUN   Test_Client_InsertNotificationsAreDeduplicatedAndDebounced
=== PAUSE Test_Client_InsertNotificationsAreDeduplicatedAndDebounced
=== RUN   Test_Client_JobCompletion
=== PAUSE Test_Client_JobCompletion
=== RUN   Test_Client_UnknownJobKindErrorsTheJob
=== PAUSE Test_Client_UnknownJobKindErrorsTheJob
=== RUN   Test_Client_Start_Error
=== PAUSE Test_Client_Start_Error
=== CONT  Test_Client
=== RUN   Test_Client/WithWorkerMiddlewareOnWorker
=== PAUSE Test_Client/WithWorkerMiddlewareOnWorker
=== CONT  Test_Client_InsertTx
=== CONT  Test_Client_JobList
=== CONT  Test_Client_JobGet
=== CONT  Test_Client_InsertManyTx
=== CONT  Test_Client_InsertMany
=== CONT  Test_Client_InsertManyFastTx
=== CONT  Test_Client/WithWorkerMiddlewareOnWorker
=== CONT  Test_Client_JobRetry
=== CONT  Test_Client_Start_Error
=== CONT  Test_Client_UnknownJobKindErrorsTheJob
--- PASS: Test_Client_InsertManyFastTx (0.00s)
--- PASS: Test_Client_Start_Error (0.00s)
=== CONT  Test_Client_RetryPolicy
=== CONT  Test_Client_InsertManyFast
--- PASS: Test_Client_InsertManyTx (0.00s)
=== CONT  Test_Client_JobCompletion
--- PASS: Test_Client_JobCompletion (0.00s)
=== CONT  Test_Client_InsertNotificationsAreDeduplicatedAndDebounced
--- PASS: Test_Client_InsertManyFast (0.00s)
=== CONT  Test_Client_InsertTriggersImmediateWork
--- PASS: Test_Client_JobGet (0.00s)
=== CONT  Test_Client_SubscribeConfig
--- PASS: Test_Client_SubscribeConfig (0.00s)
=== CONT  Test_Client_Subscribe
--- PASS: Test_Client_Subscribe (0.00s)
=== CONT  Test_Client_QueueGetTx
--- PASS: Test_Client_JobList (0.00s)
=== CONT  Test_Client_QueueListTx
--- PASS: Test_Client_QueueListTx (0.00s)
=== CONT  Test_Client_QueueList
--- PASS: Test_Client_JobRetry (0.00s)
=== CONT  Test_Client_Maintenance
--- PASS: Test_Client_Maintenance (0.00s)
=== CONT  Test_Client_QueueGet
--- PASS: Test_Client_RetryPolicy (0.00s)
=== CONT  Test_Client_StopAndCancel
--- PASS: Test_Client_StopAndCancel (0.00s)
=== CONT  Test_Client_Insert
--- PASS: Test_Client_QueueGetTx (0.00s)
=== CONT  Test_Client_JobDelete
--- PASS: Test_Client_QueueList (0.00s)
=== CONT  Test_Client_ClientFromContext
--- PASS: Test_Client_QueueGet (0.00s)
=== CONT  Test_Client_JobContextInheritsFromProvidedContext
=== CONT  Test_Client_Stop_AfterContextCancelled
--- PASS: Test_Client_Insert (0.00s)
--- PASS: Test_Client_InsertTx (0.00s)
=== CONT  Test_Client_ErrorHandler
--- PASS: Test_Client_InsertMany (0.00s)
=== CONT  Test_Client_Stop
--- PASS: Test_Client_JobDelete (0.00s)
--- PASS: Test_Client_ErrorHandler (0.00s)
--- PASS: Test_Client_Stop (0.00s)
=== NAME  Test_Client_ClientFromContext
    logger.go:256: time=2025-02-21T12:18:30.698-08:00 level=INFO msg="River client started" client_id=proximl_local_2025_02_21T20_18_30_694446

[... 100+ lines skipped ...]

We're trying to run Test_Client/WithWorkerMiddlewareOnWorker, but we
get dozens of other tests start up as well. The reason this happens is
that "/" acts as a bit of a wildcard when matching test names, so
although it'll correctly instruct Go to look into Test_Client, it'll
also have to check Test_Client_Insert and Test_Client_QueueGet
(along with many others) to see if they have matching subtests as well.

The right way to resolve this is to make sure to never do what we have
where you have test cases with subtests along with other tests that
share a root. i.e.

// don't ever do this
Test_Client
    StartInsertAndWork
    Queues_Add_WhenClientWontExecuteJobs
    WithWorkerMiddlewareOnWorker
    ...
Test_Client_JobDelete
Test_Client_ErrorHandler
...

Always pick either one convention or the other.

Unfortunately, getting this fixed at this point is going to be an
absolutely tremendous amount of work that'll be hard to pull off
easily, so I took an easier root of adding a disambiguator to the common
set of tests, so the above becomes this:

Test_Client_Common
    StartInsertAndWork
    Queues_Add_WhenClientWontExecuteJobs
    WithWorkerMiddlewareOnWorker
    ...
Test_Client_JobDelete
Test_Client_ErrorHandler
...

It's bad, but it works. Instead of the mess above, we now get this when
trying to run a single test:

$ go test . -run Test_Client_Common/WithWorkerMiddlewareOnWorker -test.v
=== RUN   Test_Client_Common
=== PAUSE Test_Client_Common
=== CONT  Test_Client_Common
=== RUN   Test_Client_Common/WithWorkerMiddlewareOnWorker
=== PAUSE Test_Client_Common/WithWorkerMiddlewareOnWorker
=== CONT  Test_Client_Common/WithWorkerMiddlewareOnWorker
    riverdbtest.go:216: Dropped 5 expired postgres schema(s) in 38.204292ms
    client_test.go:975: Generated postgres schema "river_2025_06_24t09_53_26_schema_01" with migrations [1 2 3 4 5 6] on line "main" in 34.36225ms [1 generated] [0 reused]
    logger.go:256: time=2025-06-24T09:53:26.574+02:00 level=INFO msg="River client started" client_id=proximl_local_2025_06_24T07_53_26_573178
    logger.go:256: time=2025-06-24T09:53:26.627+02:00 level=INFO msg="River client stopped" client_id=proximl_local_2025_06_24T07_53_26_573178
    riverdbtest.go:289: Checked in postgres schema "river_2025_06_24t09_53_26_schema_01"; 1 idle schema(s) [1 generated] [0 reused]
--- PASS: Test_Client_Common (0.00s)
    --- PASS: Test_Client_Common/WithWorkerMiddlewareOnWorker (0.15s)
PASS
ok      github.com/riverqueue/river     0.360s

It'd be nice not to need the *_Common convention for other things
though, so in the future, try not to share name roots between tests so
we can avoid this problem entirely.

This one's aimed at fixing a very long running problem we've had in that
it's impossible to get test output for only one specific test, which
makes debugging extremely difficult/onerous.

Here's a rough demonstration of the problem. I want to run only one test
case and get it's output:

    $ go test . -run Test_Client/WithWorkerMiddlewareOnWorker -test.v
    === RUN   Test_Client
    === PAUSE Test_Client
    === RUN   Test_Client_Stop
    === PAUSE Test_Client_Stop
    === RUN   Test_Client_Stop_AfterContextCancelled
    === PAUSE Test_Client_Stop_AfterContextCancelled
    === RUN   Test_Client_StopAndCancel
    === PAUSE Test_Client_StopAndCancel
    === RUN   Test_Client_JobContextInheritsFromProvidedContext
    === PAUSE Test_Client_JobContextInheritsFromProvidedContext
    === RUN   Test_Client_ClientFromContext
    === PAUSE Test_Client_ClientFromContext
    === RUN   Test_Client_JobDelete
    === PAUSE Test_Client_JobDelete
    === RUN   Test_Client_Insert
    === PAUSE Test_Client_Insert
    === RUN   Test_Client_InsertTx
    === PAUSE Test_Client_InsertTx
    === RUN   Test_Client_InsertManyFast
    === PAUSE Test_Client_InsertManyFast
    === RUN   Test_Client_InsertManyFastTx
    === PAUSE Test_Client_InsertManyFastTx
    === RUN   Test_Client_InsertMany
    === PAUSE Test_Client_InsertMany
    === RUN   Test_Client_InsertManyTx
    === PAUSE Test_Client_InsertManyTx
    === RUN   Test_Client_JobGet
    === PAUSE Test_Client_JobGet
    === RUN   Test_Client_JobList
    === PAUSE Test_Client_JobList
    === RUN   Test_Client_JobRetry
    === PAUSE Test_Client_JobRetry
    === RUN   Test_Client_ErrorHandler
    === PAUSE Test_Client_ErrorHandler
    === RUN   Test_Client_Maintenance
    === PAUSE Test_Client_Maintenance
    === RUN   Test_Client_QueueGet
    === PAUSE Test_Client_QueueGet
    === RUN   Test_Client_QueueGetTx
    === PAUSE Test_Client_QueueGetTx
    === RUN   Test_Client_QueueList
    === PAUSE Test_Client_QueueList
    === RUN   Test_Client_QueueListTx
    === PAUSE Test_Client_QueueListTx
    === RUN   Test_Client_RetryPolicy
    === PAUSE Test_Client_RetryPolicy
    === RUN   Test_Client_Subscribe
    === PAUSE Test_Client_Subscribe
    === RUN   Test_Client_SubscribeConfig
    === PAUSE Test_Client_SubscribeConfig
    === RUN   Test_Client_InsertTriggersImmediateWork
    === PAUSE Test_Client_InsertTriggersImmediateWork
    === RUN   Test_Client_InsertNotificationsAreDeduplicatedAndDebounced
    === PAUSE Test_Client_InsertNotificationsAreDeduplicatedAndDebounced
    === RUN   Test_Client_JobCompletion
    === PAUSE Test_Client_JobCompletion
    === RUN   Test_Client_UnknownJobKindErrorsTheJob
    === PAUSE Test_Client_UnknownJobKindErrorsTheJob
    === RUN   Test_Client_Start_Error
    === PAUSE Test_Client_Start_Error
    === CONT  Test_Client
    === RUN   Test_Client/WithWorkerMiddlewareOnWorker
    === PAUSE Test_Client/WithWorkerMiddlewareOnWorker
    === CONT  Test_Client_InsertTx
    === CONT  Test_Client_JobList
    === CONT  Test_Client_JobGet
    === CONT  Test_Client_InsertManyTx
    === CONT  Test_Client_InsertMany
    === CONT  Test_Client_InsertManyFastTx
    === CONT  Test_Client/WithWorkerMiddlewareOnWorker
    === CONT  Test_Client_JobRetry
    === CONT  Test_Client_Start_Error
    === CONT  Test_Client_UnknownJobKindErrorsTheJob
    --- PASS: Test_Client_InsertManyFastTx (0.00s)
    --- PASS: Test_Client_Start_Error (0.00s)
    === CONT  Test_Client_RetryPolicy
    === CONT  Test_Client_InsertManyFast
    --- PASS: Test_Client_InsertManyTx (0.00s)
    === CONT  Test_Client_JobCompletion
    --- PASS: Test_Client_JobCompletion (0.00s)
    === CONT  Test_Client_InsertNotificationsAreDeduplicatedAndDebounced
    --- PASS: Test_Client_InsertManyFast (0.00s)
    === CONT  Test_Client_InsertTriggersImmediateWork
    --- PASS: Test_Client_JobGet (0.00s)
    === CONT  Test_Client_SubscribeConfig
    --- PASS: Test_Client_SubscribeConfig (0.00s)
    === CONT  Test_Client_Subscribe
    --- PASS: Test_Client_Subscribe (0.00s)
    === CONT  Test_Client_QueueGetTx
    --- PASS: Test_Client_JobList (0.00s)
    === CONT  Test_Client_QueueListTx
    --- PASS: Test_Client_QueueListTx (0.00s)
    === CONT  Test_Client_QueueList
    --- PASS: Test_Client_JobRetry (0.00s)
    === CONT  Test_Client_Maintenance
    --- PASS: Test_Client_Maintenance (0.00s)
    === CONT  Test_Client_QueueGet
    --- PASS: Test_Client_RetryPolicy (0.00s)
    === CONT  Test_Client_StopAndCancel
    --- PASS: Test_Client_StopAndCancel (0.00s)
    === CONT  Test_Client_Insert
    --- PASS: Test_Client_QueueGetTx (0.00s)
    === CONT  Test_Client_JobDelete
    --- PASS: Test_Client_QueueList (0.00s)
    === CONT  Test_Client_ClientFromContext
    --- PASS: Test_Client_QueueGet (0.00s)
    === CONT  Test_Client_JobContextInheritsFromProvidedContext
    === CONT  Test_Client_Stop_AfterContextCancelled
    --- PASS: Test_Client_Insert (0.00s)
    --- PASS: Test_Client_InsertTx (0.00s)
    === CONT  Test_Client_ErrorHandler
    --- PASS: Test_Client_InsertMany (0.00s)
    === CONT  Test_Client_Stop
    --- PASS: Test_Client_JobDelete (0.00s)
    --- PASS: Test_Client_ErrorHandler (0.00s)
    --- PASS: Test_Client_Stop (0.00s)
    === NAME  Test_Client_ClientFromContext
        logger.go:256: time=2025-02-21T12:18:30.698-08:00 level=INFO msg="River client started" client_id=proximl_local_2025_02_21T20_18_30_694446

    [... 100+ lines skipped ...]

We're trying to run `Test_Client/WithWorkerMiddlewareOnWorker`, but we
get dozens of other tests start up as well. The reason this happens is
that "/" acts as a bit of a wildcard when matching test names, so
although it'll correctly instruct Go to look into `Test_Client`, it'll
also have to check `Test_Client_Insert` and `Test_Client_QueueGet`
(along with many others) to see if they have matching subtests as well.

The right way to resolve this is to make sure to never do what we have
where you have test cases with subtests along with other tests that
share a root. i.e.

    // don't ever do this
    Test_Client
        StartInsertAndWork
        Queues_Add_WhenClientWontExecuteJobs
        WithWorkerMiddlewareOnWorker
        ...
    Test_Client_JobDelete
    Test_Client_ErrorHandler
    ...

Always pick either one convention or the other.

Unfortunately, getting this fixed at this point is going to be an
absolutely tremendous amount of work that'll be hard to pull off
easily, so I took an easier root of adding a disambiguator to the common
set of tests, so the above becomes this:

    Test_Client_Common
        StartInsertAndWork
        Queues_Add_WhenClientWontExecuteJobs
        WithWorkerMiddlewareOnWorker
        ...
    Test_Client_JobDelete
    Test_Client_ErrorHandler
    ...

It's bad, but it works. Instead of the mess above, we now get this when
trying to run a single test:

    $ go test . -run Test_Client_Common/WithWorkerMiddlewareOnWorker -test.v
    === RUN   Test_Client_Common
    === PAUSE Test_Client_Common
    === CONT  Test_Client_Common
    === RUN   Test_Client_Common/WithWorkerMiddlewareOnWorker
    === PAUSE Test_Client_Common/WithWorkerMiddlewareOnWorker
    === CONT  Test_Client_Common/WithWorkerMiddlewareOnWorker
        riverdbtest.go:216: Dropped 5 expired postgres schema(s) in 38.204292ms
        client_test.go:975: Generated postgres schema "river_2025_06_24t09_53_26_schema_01" with migrations [1 2 3 4 5 6] on line "main" in 34.36225ms [1 generated] [0 reused]
        logger.go:256: time=2025-06-24T09:53:26.574+02:00 level=INFO msg="River client started" client_id=proximl_local_2025_06_24T07_53_26_573178
        logger.go:256: time=2025-06-24T09:53:26.627+02:00 level=INFO msg="River client stopped" client_id=proximl_local_2025_06_24T07_53_26_573178
        riverdbtest.go:289: Checked in postgres schema "river_2025_06_24t09_53_26_schema_01"; 1 idle schema(s) [1 generated] [0 reused]
    --- PASS: Test_Client_Common (0.00s)
        --- PASS: Test_Client_Common/WithWorkerMiddlewareOnWorker (0.15s)
    PASS
    ok      github.com/riverqueue/river     0.360s

It'd be nice not to need the `*_Common` convention for other things
though, so in the future, try not to share name roots between tests so
we can avoid this problem entirely.
@brandur
brandur requested a review from bgentry June 28, 2025 12:22
@brandur

brandur commented Jun 28, 2025

Copy link
Copy Markdown
Contributor Author

@bgentry Seem okay?

@brandur
brandur merged commit 75ab666 into master Jul 2, 2025
10 checks passed
@brandur
brandur deleted the brandur-localize-test-output branch July 2, 2025 14:05
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants