cmd/snap: make userd signal handlig easier to test, fix unit tests stall in session agent tests
We are seeing unit tests hitting execution timeout on Travis. Specifically, the
userd session agent tests are stuck.
The test in question executes a session agent, which is signalled to stop by
procuring a SIGUSR1 sent to self. While that works locally, it keeps on failing
randomly on Travis. Investigating the backtrace, it appears as if the signal was
sent (goroutine responsible for doing that is already gone), but the userd
process does not exit. It is suspected there might be a weird interaction or a
race between a prior call to setup the same signals inside the 'userd proper' test.
Provide mockable implementation of signal handling inside snap userd. Have the
signal setup tested only once.
Relevant test backtrace:
2019/07/30 14:00:20.268921 cmd_run.go:779: cannot extract runtime data: cannot parse end of exec profile: EOF
panic: test timed out after 5m0s
goroutine 2461 [running]:
testing.startAlarm.func1()
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/testing/testing.go:1145 +0xf9
created by time.goFunc
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/time/sleep.go:170 +0x44
goroutine 1 [chan receive, 5 minutes]:
testing.(*T).Run(0xc4200da000, 0xc7d924, 0x4, 0xccdb18, 0x485b66)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/testing/testing.go:790 +0x2fc
testing.runTests.func1(0xc4200da000)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/testing/testing.go:1004 +0x64
testing.tRunner(0xc4200da000, 0xc420487de0)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/testing/testing.go:746 +0xd0
testing.runTests(0xc420094180, 0x10b04b0, 0x1, 0x1, 0xc00200dc100)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/testing/testing.go:1002 +0x2d8
testing.(*M).Run(0xc4204d1f18, 0xc420487f70)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/testing/testing.go:921 +0x111
main.main()
github.com/snapcore/snapd/cmd/snap/_test/_testmain.go:46 +0xdb
goroutine 19 [syscall, 5 minutes]:
os/signal.signal_recv(0x0)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/runtime/sigqueue.go:131 +0xa6
os/signal.loop()
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/os/signal/signal_unix.go:22 +0x22
created by os/signal.init.0
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/os/signal/signal_unix.go:28 +0x41
goroutine 23 [chan receive, 4 minutes]:
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*suiteRunner).runTest(0xc420278000, 0xc42019e540, 0x0)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:819 +0x55
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*suiteRunner).run(0xc420278000, 0xc42012a000)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:624 +0xfc
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.Run(0xc4e940, 0xc42012a000, 0xc42008c680, 0xc42012a7e0)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/run.go:92 +0x4d
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.RunAll(0xc42008c680, 0x0)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/run.go:84 +0xa4
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.TestingT(0xc4200da0f0)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/run.go:72 +0x386
github.com/snapcore/snapd/cmd/snap_test.Test(0xc4200da0f0)
/home/travis/gopath/src/github.com/snapcore/snapd/cmd/snap/main_test.go:50 +0x2b
testing.tRunner(0xc4200da0f0, 0xccdb18)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/testing/testing.go:746 +0xd0
created by testing.(*T).Run
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/testing/testing.go:789 +0x2de
goroutine 2455 [chan receive, 4 minutes]:
github.com/snapcore/snapd/vendor/github.com/godbus/dbus.(*Conn).outWorker(0xc4200dc400)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/github.com/godbus/dbus/conn.go:427 +0x63
created by github.com/snapcore/snapd/vendor/github.com/godbus/dbus.(*Conn).Auth
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/github.com/godbus/dbus/auth.go:119 +0x701
goroutine 2454 [IO wait, 4 minutes]:
internal/poll.runtime_pollWait(0x7f79246fae28, 0x72, 0x0)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc420278098, 0x72, 0xc420507300, 0x1000, 0x0)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/internal/poll/fd_poll_runtime.go:85 +0xae
internal/poll.(*pollDesc).waitRead(0xc420278098, 0xc4202f0600, 0x10, 0x10)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).ReadMsg(0xc420278080, 0xc4202f0660, 0x10, 0x10, 0xc420507320, 0x1000, 0x1000, 0x0, 0x0, 0x0, ...)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/internal/poll/fd_unix.go:194 +0x222
net.(*netFD).readMsg(0xc420278080, 0xc4202f0660, 0x10, 0x10, 0xc420507320, 0x1000, 0x1000, 0x0, 0xb76900, 0xc4202a0470, ...)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/net/fd_unix.go:214 +0x90
net.(*UnixConn).readMsg(0xc4206069a8, 0xc4202f0660, 0x10, 0x10, 0xc420507320, 0x1000, 0x1000, 0x9, 0xc4202f04f8, 0x1080fe0, ...)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/net/unixsock_posix.go:115 +0x91
net.(*UnixConn).ReadMsgUnix(0xc4206069a8, 0xc4202f0660, 0x10, 0x10, 0xc420507320, 0x1000, 0x1000, 0x1071f40, 0xc4205225b0, 0x7, ...)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/net/unixsock.go:137 +0xaa
github.com/snapcore/snapd/vendor/github.com/godbus/dbus.(*oobReader).Read(0xc420507300, 0xc4202f0660, 0x10, 0x10, 0xc420507300, 0x7f79246e0030, 0x0)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/github.com/godbus/dbus/transport_unix.go:21 +0x8f
io.ReadAtLeast(0x1074340, 0xc420507300, 0xc4202f0660, 0x10, 0x10, 0x10, 0xbffa20, 0xb63d01, 0xc420507300)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/io/io.go:309 +0x86
io.ReadFull(0x1074340, 0xc420507300, 0xc4202f0660, 0x10, 0x10, 0x9, 0x0, 0x0)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/io/io.go:327 +0x58
github.com/snapcore/snapd/vendor/github.com/godbus/dbus.(*unixTransport).ReadMessage(0xc42055e240, 0xccdd08, 0xc4200dc400, 0xc42034e090)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/github.com/godbus/dbus/transport_unix.go:85 +0x115
github.com/snapcore/snapd/vendor/github.com/godbus/dbus.(*Conn).inWorker(0xc4200dc400)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/github.com/godbus/dbus/conn.go:285 +0x4b
created by github.com/snapcore/snapd/vendor/github.com/godbus/dbus.(*Conn).Auth
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/github.com/godbus/dbus/auth.go:118 +0x6dc
goroutine 515 [select, 4 minutes, locked to thread]:
runtime.gopark(0xcce8c8, 0x0, 0xc7ff57, 0x6, 0x18, 0x1)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/runtime/proc.go:287 +0x12c
runtime.selectgo(0xc4205f7f50, 0xc42049c660)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/runtime/select.go:395 +0x1149
runtime.ensureSigM.func1()
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/runtime/signal_unix.go:511 +0x220
runtime.goexit()
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/runtime/asm_amd64.s:2337 +0x1
goroutine 2452 [select, 4 minutes]:
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*resultTracker)._loopRoutine(0xc42044e000)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:470 +0xff
created by github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*resultTracker).start
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:450 +0x3f
goroutine 2440 [IO wait, 4 minutes]:
internal/poll.runtime_pollWait(0x7f79246fd300, 0x72, 0xffffffffffffffff)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/runtime/netpoll.go:173 +0x57
internal/poll.(*pollDesc).wait(0xc42035ae98, 0x72, 0xc4205f8c00, 0x0, 0x0)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/internal/poll/fd_poll_runtime.go:85 +0xae
internal/poll.(*pollDesc).waitRead(0xc42035ae98, 0xffffffffffffff00, 0x0, 0x0)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Accept(0xc42035ae80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/internal/poll/fd_unix.go:335 +0x1e2
net.(*netFD).accept(0xc42035ae80, 0xc420270120, 0xb9ad00, 0xc4205f8e50)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/net/fd_unix.go:238 +0x42
net.(*UnixListener).accept(0xc4204d9020, 0x7ee3f8, 0x45ba60, 0xc4205f8e98)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/net/unixsock_posix.go:162 +0x32
net.(*UnixListener).Accept(0xc4204d9020, 0xcce1f8, 0xc4202700a0, 0x107ed40, 0xc4205d62a0)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/net/unixsock.go:241 +0x49
net/http.(*Server).Serve(0xc4203f3e10, 0x107de80, 0xc4204d9020, 0x0, 0x0)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/net/http/server.go:2695 +0x1b2
github.com/snapcore/snapd/usersession/agent.(*SessionAgent).Start.func1(0xc420436000, 0xccde68)
/home/travis/gopath/src/github.com/snapcore/snapd/usersession/agent/session_agent.go:107 +0x49
github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).run(0xc42035aca8, 0xc4202a0e00)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:163 +0x2b
created by github.com/snapcore/snapd/vendor/gopkg.in/tomb%2ev2.(*Tomb).Go
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/tomb.v2/tomb.go:159 +0xc0
goroutine 2437 [select, 4 minutes]:
github.com/snapcore/snapd/cmd/snap.(*cmdUserd).runAgent(0xc4202f0cc8, 0x0, 0x0)
/home/travis/gopath/src/github.com/snapcore/snapd/cmd/snap/cmd_userd.go:111 +0x250
github.com/snapcore/snapd/cmd/snap.(*cmdUserd).Execute(0xc4202f0cc8, 0xc4208849e0, 0x0, 0x2, 0xc4202f0cc8, 0x1)
/home/travis/gopath/src/github.com/snapcore/snapd/cmd/snap/cmd_userd.go:72 +0x4c
github.com/snapcore/snapd/vendor/github.com/jessevdk/go-flags.(*Parser).ParseArgs(0xc42019eb60, 0xc420884940, 0x2, 0x2, 0xc42004dab0, 0x4b39a3, 0xc4e940, 0xc420505320, 0x10)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/github.com/jessevdk/go-flags/parser.go:333 +0x849
github.com/snapcore/snapd/cmd/snap_test.(*userdSuite).TestSessionAgentSocket(0xc42012a000, 0xc4204360f0)
/home/travis/gopath/src/github.com/snapcore/snapd/cmd/snap/cmd_userd_test.go:148 +0xea
reflect.Value.call(0xc4e940, 0xc42012a000, 0x2e13, 0xc7d728, 0x4, 0xc42004df70, 0x1, 0x1, 0x10e5b00, 0xc6fca0, ...)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/reflect/value.go:434 +0x905
reflect.Value.Call(0xc4e940, 0xc42012a000, 0x2e13, 0xc420600f70, 0x1, 0x1, 0xc4204361e0, 0xc420600f07, 0xc4203c5e00)
/home/travis/.gimme/versions/go1.9.7.linux.amd64/src/reflect/value.go:302 +0xa4
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*suiteRunner).forkTest.func1(0xc4204360f0)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:781 +0x588
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*suiteRunner).forkCall.func1(0xc420278000, 0xc4204360f0, 0xc420334a80)
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:675 +0x7c
created by github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*suiteRunner).forkCall
/home/travis/gopath/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:672 +0x218
FAIL github.com/snapcore/snapd/cmd/snap 300.148s
=== RUN Test
OK: 22 passed
--- PASS: Test (0.08s)
Signed-off-by: Maciej Borzecki <email address hidden>
