[CI]: events filter sometimes does not work

[apostasie]

Description

Here is an example from the CI where event filter does not produce on stdout the expected output.
(ignore the timeout aspect, which is by design)

It is unclear if this is a test issue, or a code issue related to events.

I have seen this before, but it is awfully rare it happens regularly on EL, so, this is likely going to be very hard a bit of a trek to debug.

Steps to reproduce the issue

Describe the results you received and expected

test target: "nerdctl"
PASS cmd/nerdctl/system.TestSystemPrune/buildkit (2.04s)
PASS cmd/nerdctl/system.TestSystemPrune/volume_prune_all_success (2.33s)
PASS cmd/nerdctl/system.TestSystemPrune (2.04s)
PASS cmd/nerdctl/system.TestInfo/info_convenience_form (0.02s)
PASS cmd/nerdctl/system.TestInfo/info (0.02s)
PASS cmd/nerdctl/system.TestEventFilters/CapitalizedFilter (10.01s)
PASS cmd/nerdctl/system.TestEventFilters/UnsupportedEventFilter (10.01s)
PASS cmd/nerdctl/system.TestInfo/info_with_namespace (0.01s)
PASS cmd/nerdctl/system.TestInfo/info_with_namespace_env_var (0.02s)
PASS cmd/nerdctl/system.TestInfo (0.00s)
PASS cmd/nerdctl/system.TestEventFilters/UnsupportedStatusFilter (10.01s)
PASS cmd/nerdctl/system.TestEventFilters/StatusFilter (10.00s)
=== RUN   TestEventFilters/StartEventFilter
=== PAUSE TestEventFilters/StartEventFilter
=== CONT  TestEventFilters/StartEventFilter
    command.go:461: [2025-04-19T01:00:54Z] [command=/usr/local/bin/nerdctl --namespace=nerdctl-test events --filter event=start --format json] command cancelled
    system_events_linux_test.go:36: 
        
        +------------------------------------------------------------------------------------------------------------+
        | ➡️      | ⚙️ /usr/local/bin/nerdctl run --rm ghcr.io/stargz-containers/alpine:3.13-org                     |
        +------------------------------------------------------------------------------------------------------------+
        | 🌱      | HOME=/root                                                                                       |
        |         | PATH=/usr/local/go/bin:/usr/local/go/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin |
        |         | :/bin                                                                                            |
        |         | DOCKER_CONFIG=/tmp/TestEventFiltersStartEventFilter558665065/003                                 |
        |         | NERDCTL_TOML=/tmp/TestEventFiltersStartEventFilter558665065/003/nerdctl.toml                     |
        +------------------------------------------------------------------------------------------------------------+
        | ⏰      | 14.396060745s (limit: 3m0s)                                                                      |
        +------------------------------------------------------------------------------------------------------------+
        | 📁      | /tmp/TestEventFiltersStartEventFilter558665065/002                                               |
        +------------------------------------------------------------------------------------------------------------+
        
    system_events_linux_test.go:119: 
        
        +============================================================================================================+
        | 🚀      | "TestEventFilters/StartEventFilter": starting test!                                              |
        +============================================================================================================+
        | ⏳      | /tmp/TestEventFiltersStartEventFilter558665065/001/66ac0bc7                                      |
        +============================================================================================================+
        |         |                                                                                                  |
        +============================================================================================================+
        | config  | {                                                                                                |
        |         |   "Namespace": "nerdctl-test",                                                                   |
        |         |   "PrivateMode": ""                                                                              |
        |         | }                                                                                                |
        +============================================================================================================+
        | labels  | {}                                                                                               |
        +============================================================================================================+
        
    system_events_linux_test.go:119: 
        
        +------------------------------------------------------------------------------------------------------------+
        | ➡️      | ⚙️ /usr/local/bin/nerdctl events --filter event=start --format json                              |
        +------------------------------------------------------------------------------------------------------------+
        |         | 🚫 command timed out                                                                             |
        +------------------------------------------------------------------------------------------------------------+
        |         | ⚠️ -1                                                                                            |
        +------------------------------------------------------------------------------------------------------------+
        |         | ⚡ killed                                                                                        |
        +------------------------------------------------------------------------------------------------------------+
        | 🌱      | HOME=/root                                                                                       |
        |         | PATH=/usr/local/go/bin:/usr/local/go/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin |
        |         | :/bin                                                                                            |
        |         | DOCKER_CONFIG=/tmp/TestEventFiltersStartEventFilter558665065/003                                 |
        |         | NERDCTL_TOML=/tmp/TestEventFiltersStartEventFilter558665065/003/nerdctl.toml                     |
        +------------------------------------------------------------------------------------------------------------+
        | ⏰      | 14.39958[849](https://github.com/containerd/nerdctl/actions/runs/14543995202/job/40806895106?pr=4103#step:7:850)6s (limit: 10s)                                                                       |
        +------------------------------------------------------------------------------------------------------------+
        | 📁      | /tmp/TestEventFiltersStartEventFilter558665065/002                                               |
        +------------------------------------------------------------------------------------------------------------+
        
    system_events_linux_test.go:119: 	
        
        <<<<<<<<<<<<<<<<<<<<
        	🖊️ Command should time-out
        	👀 testing:		`command timed out`
        	✅️ does verify:		is `command timed out`
        >>>>>>>>>>>>>>>>>>>>
        
    system_events_linux_test.go:119: 	
        
        <<<<<<<<<<<<<<<<<<<<
        	🖊️ Inspecting output (contains)
        	👀 testing:		``
        	❌ FAILED!		~= `tatus":"start"`
        >>>>>>>>>>>>>>>>>>>>
        
--- FAIL: TestEventFilters/StartEventFilter (14.40s)
FAIL cmd/nerdctl/system.TestEventFilters/StartEventFilter (14.40s)
=== RUN   TestEventFilters
=== PAUSE TestEventFilters
=== CONT  TestEventFilters
    system_events_linux_test.go:119: 
        ⤵️️ "TestEventFilters": into subtests prep
    system_events_linux_test.go:119: 
        ↩️️ "TestEventFilters": done with subtests prep
--- FAIL: TestEventFilters (0.00s)
FAIL cmd/nerdctl/system.TestEventFilters (0.00s)

What version of nerdctl are you using?

main

Are you using a variant of nerdctl? (e.g., Rancher Desktop)

None

Host information

No response

[fahedouch]

@apostasie

Maybe I am missing something, but it seems we can check the expected output only in synchronous mode.

Another point: it looks like when running in background mode, we don't stop but continue to gc.cmd.Wait().

[apostasie]

@fahedouch test.Command code is a bit of a train accident now (following recent work on internal command, so, it needs a cleanup).

Anyhow, this seems to work as expected:

func TestCommand(t *testing.T) {
	t.Parallel()

	com := NewGenericCommand()
	com.(*GenericCommand).withT(t)

	com.WithBinary("bash")
	com.WithArgs("-c", "--", "echo foo; sleep inf;")
	com.WithTimeout(5 * time.Second)

	com.Background()

         // ... do whatever while com is running in the background


        // Now foreground cmd, wait for it (it will timeout in that case), and test the output
	com.Run(&Expected{
		ExitCode: -12,
		Errors:   nil,
		Output: func(stdout, info string, t *testing.T) {
			assert.Equal(t, "foo\n", stdout)
		},
	})
}

Does that clarify?

[apostasie]

To your point: the API and method names probably need to be rethought. In the context above Run sounds counter-intuitive, since the (backgrounded) command is already running.

I have a pile of things I want to change that is impacting the API - given this will require large changes in nerdctl tests, I want to batch them all together to minimize disruption.

[Shubhranshu153]

https://github.com/containerd/nerdctl/pull/4196/files -> does the pre pull fix in the pr fixes this one, from what i saw it was due to timeout of the run commands as a result the event filters never got the events.

[apostasie]

https://github.com/containerd/nerdctl/pull/4196/files -> does the pre pull fix in the pr fixes this one, from what i saw it was due to timeout of the run commands as a result the event filters never got the events.

Thanks @Shubhranshu153 .

Closing then.