Skip to content

o/i/apparmorprompting: fix potential races when logging in tests #17023

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
olivercalder merged 1 commit into from
May 5, 2026
Merged

o/i/apparmorprompting: fix potential races when logging in tests #17023

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
24 changes: 12 additions & 12 deletions overlord/ifacestate/apparmorprompting/prompting_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -296,6 +296,7 @@ func (s *apparmorpromptingSuite) TestHandleRequestErrors(c *C) {
allowedPermissions, err := waitForReply(replyChan)
c.Assert(err, IsNil)
c.Check(allowedPermissions, DeepEquals, []string{})

logger.WithLoggerLock(func() {
c.Check(logbuf.String(), testutil.Contains,
" WARNING: too many outstanding prompts for user 1000; auto-denying new one\n")
Expand Down Expand Up @@ -1742,13 +1743,11 @@ func (s *apparmorpromptingSuite) TestListenerReadyAfterPromptsReady(c *C) {
c.Errorf("manager should still be ready")
}

time.Sleep(50 * time.Millisecond)

@andrewphelpsj andrewphelpsj May 5, 2026

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lol what was this doing here

@olivercalder olivercalder May 5, 2026

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Basically what it said on the tin, waiting to give a chance for the message to be logged (though it shouldn't be). There's some annoyingness with the synchronization with mocked listener here, we don't have a synchronization point other than the run loop in o/i/a/prompting.go, so triggering the listener readiness isn't sufficient to know that the run loop has picked up the event and handled it.

But the nice thing is, mgr.Stop() is a synchronization point, since it kills the tomb and waits for it. And <-m.tomb.Dying() is in the run loop select, so if the manager stops, we know that the prior event is done being handled.

c.Assert(mgr.Stop(), IsNil)

logger.WithLoggerLock(func() {
c.Check(logbuf.String(), Not(testutil.Contains), "listener signalled readiness and no outstanding requests were pruned")
})

c.Assert(mgr.Stop(), IsNil)
}

func (s *apparmorpromptingSuite) TestListenerReadyAfterPromptsNotReady(c *C) {
Expand Down Expand Up @@ -1787,13 +1786,10 @@ func (s *apparmorpromptingSuite) TestListenerReadyAfterPromptsNotReady(c *C) {

time.Sleep(50 * time.Millisecond)

logger.WithLoggerLock(func() {
c.Check(logbuf.String(), testutil.Contains, "listener signalled readiness and no outstanding requests were pruned")
})

c.Assert(mgr.Stop(), IsNil)

logger.WithLoggerLock(func() {
c.Check(logbuf.String(), testutil.Contains, "listener signalled readiness and no outstanding requests were pruned")
c.Check(logbuf.String(), Not(testutil.Contains), "timed out waiting for requests to be re-received after snap restart: \"api:foo\"\n")
})
}
Expand Down Expand Up @@ -1966,11 +1962,11 @@ func (s *apparmorpromptingSuite) TestListenerReadyNotCausesPromptsHandleReadying
// all good
}

logger.WithLoggerLock(func() {
c.Check(logbuf.String(), testutil.Contains, `requests timed out in the kernel while snapd was restarting: "kernel:1", "kernel:3"`)
c.Check(logbuf.String(), Not(testutil.Contains), "requests timed out in the kernel while snapd was restarting: \n")
c.Check(logbuf.String(), Not(testutil.Contains), "listener signalled readiness and no outstanding prompts were pruned")
})
// The following message should now be in the logbuf, but don't check until the end to avoid race:
// - `requests timed out in the kernel while snapd was restarting: "kernel:1", "kernel:3"`
// The following messages should *not* be in the logbuf, but again don't check until the end:
// - "requests timed out in the kernel while snapd was restarting: \n"
// - "listener signalled readiness and no outstanding prompts were pruned"

// Now add remaining API requests via Ask()

Expand Down Expand Up @@ -2034,7 +2030,11 @@ func (s *apparmorpromptingSuite) TestListenerReadyNotCausesPromptsHandleReadying

c.Assert(mgr.Stop(), IsNil)

// Now check logs since the manager has stopped and we won't have a race
logger.WithLoggerLock(func() {
c.Check(logbuf.String(), testutil.Contains, `requests timed out in the kernel while snapd was restarting: "kernel:1", "kernel:3"`)
c.Check(logbuf.String(), Not(testutil.Contains), "requests timed out in the kernel while snapd was restarting: \n")
c.Check(logbuf.String(), Not(testutil.Contains), "listener signalled readiness and no outstanding prompts were pruned")
c.Check(logbuf.String(), Not(testutil.Contains), "timed out waiting for requests to be re-received after snap restart:")
})
}
Expand Down
Loading