Panic: unlocking unlocked mutex in unit test snapd-master on riscv64

[Zygmunt Krynicki]

From https://launchpad.net/~snappy-dev/+archive/ubuntu/edge/+build/19095552

ok github.com/snapcore/snapd/overlord/snapshotstate/backend 4.671s
AppArmor status: apparmor not enabled
=== RUN TestSnapManager
fatal error: sync: unlock of unlocked mutex

goroutine 5300 [running]:
runtime.throw(0x819084, 0x1e)
 /usr/lib/go-1.10/src/runtime/panic.go:616 +0x60 fp=0x11919a48 sp=0x11919a3c pc=0x3ecdc
sync.throw(0x819084, 0x1e)
 /usr/lib/go-1.10/src/runtime/panic.go:605 +0x24 fp=0x11919a54 sp=0x11919a48 pc=0x3ec6c
sync.(*Mutex).Unlock(0x117d7a90)
 /usr/lib/go-1.10/src/sync/mutex.go:184 +0xdc fp=0x11919a6c sp=0x11919a54 pc=0x710b4
github.com/snapcore/snapd/overlord/state.(*State).unlock(0x117d7a90)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/overlord/state/state.go:162 +0x38 fp=0x11919a7c sp=0x11919a6c pc=0x3e7f98
github.com/snapcore/snapd/overlord/state.(*State).Unlock(0x117d7a90)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/overlord/state/state.go:239 +0x224 fp=0x11919ae0 sp=0x11919a7c pc=0x3e8638
runtime.call16(0x0, 0x8aa918, 0x1183215c, 0x4, 0x4)
 /usr/lib/go-1.10/src/runtime/asm_arm.s:518 +0x4c fp=0x11919af4 sp=0x11919ae0 pc=0x69c4c
runtime.Goexit()
 /usr/lib/go-1.10/src/runtime/panic.go:377 +0x15c fp=0x11919b1c sp=0x11919af4 pc=0x3e150
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*C).stopNow(0x118d3ea0)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:106 +0x14 fp=0x11919b20 sp=0x11919b1c pc=0x49b77c
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*C).Assert(0x118d3ea0, 0x75f980, 0x11838270, 0x936c48, 0xcb0954, 0x0, 0x0, 0x0)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/helpers.go:174 +0x80 fp=0x11919b50 sp=0x11919b20 pc=0x4a1af4
github.com/snapcore/snapd/overlord/snapstate_test.(*snapmgrTestSuite).settle(0x115f8f80, 0x118d3ea0)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/overlord/snapstate/snapstate_test.go:88 +0x84 fp=0x11919b74 sp=0x11919b50 pc=0x60c748
github.com/snapcore/snapd/overlord/snapstate_test.(*snapmgrTestSuite).testUpdateScenario(0x115f8f80, 0x118d3ea0, 0x829bbf, 0x2e, 0x8074ae, 0xd, 0x8074ae, 0xd, 0x7ffb14, 0x0, ...)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/overlord/snapstate/snapstate_test.go:10273 +0x474 fp=0x11919ce4 sp=0x11919b74 pc=0x6773c8
github.com/snapcore/snapd/overlord/snapstate_test.(*snapmgrTestSuite).TestUpdateScenarios(0x115f8f80, 0x118d3ea0)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/overlord/snapstate/snapstate_test.go:10236 +0x98 fp=0x11919da4 sp=0x11919ce4 pc=0x676f20
runtime.call16(0x11833da0, 0x118397c8, 0x118f9670, 0x8, 0x8)
 /usr/lib/go-1.10/src/runtime/asm_arm.s:518 +0x4c fp=0x11919db8 sp=0x11919da4 pc=0x69c4c
reflect.Value.call(0x7fe0b0, 0x115f8f80, 0x5ee13, 0x8002ae, 0x4, 0x1190ffbc, 0x1, 0x1, 0x6d1f4574, 0x7f7578, ...)
 /usr/lib/go-1.10/src/reflect/value.go:447 +0x6b0 fp=0x11919f24 sp=0x11919db8 pc=0xc0e7c
reflect.Value.Call(0x7fe0b0, 0x115f8f80, 0x5ee13, 0x1190ffbc, 0x1, 0x1, 0x118d3f40, 0x1190ff7c, 0x4)
 /usr/lib/go-1.10/src/reflect/value.go:308 +0x74 fp=0x11919f54 sp=0x11919f24 pc=0xc06f8
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*suiteRunner).forkTest.func1(0x118d3ea0)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:781 +0x4f4 fp=0x11919fc8 sp=0x11919f54 pc=0x4a5658
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*suiteRunner).forkCall.func1(0x11830370, 0x118d3ea0, 0x1191db40)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:675 +0x64 fp=0x11919fdc sp=0x11919fc8 pc=0x4a5058
runtime.goexit()
 /usr/lib/go-1.10/src/runtime/asm_arm.s:1015 +0x4 fp=0x11919fdc sp=0x11919fdc pc=0x6b864
created by github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*suiteRunner).forkCall
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:672 +0x1a0

goroutine 1 [chan receive, 1 minutes]:
testing.(*T).Run(0x1163bc20, 0x808ed9, 0xf, 0x8aa904, 0xc7231e)
 /usr/lib/go-1.10/src/testing/testing.go:825 +0x268
testing.runTests.func1(0x1163bc20)
 /usr/lib/go-1.10/src/testing/testing.go:1063 +0x50
testing.tRunner(0x1163bc20, 0x115a7eec)
 /usr/lib/go-1.10/src/testing/testing.go:777 +0xb0
testing.runTests(0x115ebfe0, 0xcb1ef8, 0x1, 0x1, 0x22128)
 /usr/lib/go-1.10/src/testing/testing.go:1061 +0x230
testing.(*M).Run(0x115f8fc0, 0x0)
 /usr/lib/go-1.10/src/testing/testing.go:978 +0x138
main.main()
 _testmain.go:44 +0x140

goroutine 5 [chan receive]:
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*suiteRunner).runTest(0x11830370, 0x1183e300, 0x11521a40)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:819 +0x40
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*suiteRunner).run(0x11830370, 0x115f8f80)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:624 +0xd4
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.Run(0x7fe0b0, 0x115f8f80, 0x11834000, 0x11830000)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/run.go:92 +0x38
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.RunAll(0x11834000, 0x0)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/run.go:84 +0x84
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.TestingT(0x1163bcb0)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/run.go:72 +0x31c
github.com/snapcore/snapd/overlord/snapstate_test.TestSnapManager(0x1163bcb0)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/overlord/snapstate/snapstate_test.go:67 +0x1c
testing.tRunner(0x1163bcb0, 0x8aa904)
 /usr/lib/go-1.10/src/testing/testing.go:777 +0xb0
created by testing.(*T).Run
 /usr/lib/go-1.10/src/testing/testing.go:824 +0x250

goroutine 707 [select]:
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*resultTracker)._loopRoutine(0x118302d0)
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:470 +0xc0
created by github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*resultTracker).start
 /<<BUILDDIR>>/snapd-2.44.1~14.04+git1691.0c83e8e~ubuntu14.04.1/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:450 +0x2c
FAIL github.com/snapcore/snapd/overlord/snapstate 90.519s

[Dimitri John Ledkov (xnox)]

This used to happen on armhf, but now happens on riscv64.

What was done to fix this on armhf? and what should be done to fix this on riscv64?

In

https://code.launchpad.net/~snappy-dev/+recipe/snapd-vendor-daily-focal

see latest riscv64 build which fails as in the bug description:

I.e. https://launchpadlibrarian.net/483684115/buildlog_ubuntu-focal-riscv64.snapd_2.45.1+git1962.18d7e0b~ubuntu20.04.1_BUILDING.txt.gz

[Dimitri John Ledkov (xnox)]

Tried to bump one timeout, yet this is still happening on riscv64

=== RUN TestSnapManager
fatal error: sync: unlock of unlocked mutex

goroutine 5186 [running]:
runtime.throw(0x2aab7d35e0, 0x1e)
 /usr/lib/go-1.14/src/runtime/panic.go:1116 +0x80 fp=0x3fcc4c2e38 sp=0x3fcc4c2e10 pc=0x2aaaf06678
sync.throw(0x2aab7d35e0, 0x1e)
 /usr/lib/go-1.14/src/runtime/panic.go:1102 +0x34 fp=0x3fcc4c2e50 sp=0x3fcc4c2e38 pc=0x2aaaf065f4
sync.(*Mutex).unlockSlow(0x3fcc1d9680, 0xffffffff)
 /usr/lib/go-1.14/src/sync/mutex.go:196 +0x17c fp=0x3fcc4c2e70 sp=0x3fcc4c2e50 pc=0x2aaaf4e224
sync.(*Mutex).Unlock(0x3fcc1d9680)
 /usr/lib/go-1.14/src/sync/mutex.go:190 +0x74 fp=0x3fcc4c2e90 sp=0x3fcc4c2e70 pc=0x2aaaf4e0a4
github.com/snapcore/snapd/overlord/state.(*State).unlock(0x3fcc1d9680)
 /<<PKGBUILDDIR>>/_build/src/github.com/snapcore/snapd/overlord/state/state.go:162 +0x4c fp=0x3fcc4c2eb0 sp=0x3fcc4c2e90 pc=0x2aab4212f4
github.com/snapcore/snapd/overlord/state.(*State).Unlock(0x3fcc1d9680)
 /<<PKGBUILDDIR>>/_build/src/github.com/snapcore/snapd/overlord/state/state.go:239 +0x284 fp=0x3fcc4c2f78 sp=0x3fcc4c2eb0 pc=0x2aab421bac
runtime.call32(0x0, 0x2aabb56388, 0x3fcc09b178)
 /usr/lib/go-1.14/src/runtime/asm_riscv64.s:486 +0x5c fp=0x3fcc4c2fa0 sp=0x3fcc4c2f78 pc=0x2aaaf40efc
runtime.reflectcallSave(0x3fcc4c3098, 0x2aabb56388, 0x3fcc09b178, 0x8)
 /usr/lib/go-1.14/src/runtime/panic.go:881 +0x60 fp=0x3fcc4c2fd0 sp=0x3fcc4c2fa0 pc=0x2aaaf05ba0
runtime.runOpenDeferFrame(0x3fcc1f5500, 0x3fcc09b130, 0x3fcc4c30d0)
 /usr/lib/go-1.14/src/runtime/panic.go:855 +0x360 fp=0x3fcc4c3058 sp=0x3fcc4c2fd0 pc=0x2aaaf05a20
runtime.Goexit()
 /usr/lib/go-1.14/src/runtime/panic.go:617 +0x1ec fp=0x3fcc4c30d0 sp=0x3fcc4c3058 pc=0x2aaaf05054
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*C).stopNow(...)
 /<<PKGBUILDDIR>>/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:106
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*C).Assert(0x3fcc446c30, 0x2aaba50c40, 0x3fcc840070, 0x2aabb7d040, 0x2aac15e510, 0x0, 0x0, 0x0)
 /<<PKGBUILDDIR>>/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/helpers.go:174 +0x94 fp=0x3fcc4c3130 sp=0x3fcc4c30d0 pc=0x2aab517934
github.com/snapcore/snapd/overlord/snapstate_test.(*snapmgrTestSuite).settle(0x3fcc0c6000, 0x3fcc446c30)
 /<<PKGBUILDDIR>>/_build/src/github.com/snapcore/snapd/overlord/snapstate/snapstate_test.go:87 +0xb0 fp=0x3fcc4c3178 sp=0x3fcc4c3130 pc=0x2aab703850
github.com/snapcore/snapd/overlord/snapstate_test.(*snapmgrTestSuite).TestUpdateManyMultipleCredsNoUserRunThrough(0x3fcc0c6000, 0x3fcc446c30)
 /<<PKGBUILDDIR>>/_build/src/github.com/snapcore/snapd/overlord/snapstate/snapstate_test.go:3642 +0x854 fp=0x3fcc4c3bb0 sp=0x3fcc4c3178 pc=0x2aab731fec
runtime.call32(0x3fcc443d70, 0x3fcc87a4c0, 0x3fcc431a30)
 /usr/lib/go-1.14/src/runtime/asm_riscv64.s:486 +0x5c fp=0x3fcc4c3bd8 sp=0x3fcc4c3bb0 pc=0x2aaaf40efc
reflect.Value.call(0x2aabb53be0, 0x3fcc0c6000, 0x59613, 0x2aab7b8375, 0x4, 0x3fcc075f18, 0x1, 0x1, 0x2aaaf3e970, 0x2aac1e4ae0, ...)
 /usr/lib/go-1.14/src/reflect/value.go:460 +0x77c fp=0x3fcc4c3de8 sp=0x3fcc4c3bd8 pc=0x2aaafb3504
reflect.Value.Call(0x2aabb53be0, 0x3fcc0c6000, 0x59613, 0x3fcc062f18, 0x1, 0x1, 0x3f...

[Dimitri John Ledkov (xnox)]

Failed on riscv64 8h ago at

https://code.launchpad.net/~snappy-dev/+archive/ubuntu/edge/+build/19459842

=== RUN TestSnapManager
fatal error: sync: unlock of unlocked mutex

goroutine 5673 [running]:
runtime.throw(0x2aab7d3480, 0x1e)
 /usr/lib/go-1.14/src/runtime/panic.go:1116 +0x80 fp=0x3fcc57f4c8 sp=0x3fcc57f4a0 pc=0x2aaaf06648
sync.throw(0x2aab7d3480, 0x1e)
 /usr/lib/go-1.14/src/runtime/panic.go:1102 +0x34 fp=0x3fcc57f4e0 sp=0x3fcc57f4c8 pc=0x2aaaf065c4
sync.(*Mutex).unlockSlow(0x3fcc33aab0, 0x3fffffffff)
 /usr/lib/go-1.14/src/sync/mutex.go:196 +0x17c fp=0x3fcc57f500 sp=0x3fcc57f4e0 pc=0x2aaaf4e1f4
sync.(*Mutex).Unlock(0x3fcc33aab0)
 /usr/lib/go-1.14/src/sync/mutex.go:190 +0x74 fp=0x3fcc57f520 sp=0x3fcc57f500 pc=0x2aaaf4e074
github.com/snapcore/snapd/overlord/state.(*State).unlock(0x3fcc33aab0)
 /<<PKGBUILDDIR>>/_build/src/github.com/snapcore/snapd/overlord/state/state.go:162 +0x4c fp=0x3fcc57f540 sp=0x3fcc57f520 pc=0x2aab421204
github.com/snapcore/snapd/overlord/state.(*State).Unlock(0x3fcc33aab0)
 /<<PKGBUILDDIR>>/_build/src/github.com/snapcore/snapd/overlord/state/state.go:239 +0x284 fp=0x3fcc57f608 sp=0x3fcc57f540 pc=0x2aab421abc
runtime.call32(0x0, 0x2aabb554a8, 0x3fcc5b1448)
 /usr/lib/go-1.14/src/runtime/asm_riscv64.s:486 +0x5c fp=0x3fcc57f630 sp=0x3fcc57f608 pc=0x2aaaf40ecc
runtime.reflectcallSave(0x3fcc57f728, 0x2aabb554a8, 0x3fcc5b1448, 0x8)
 /usr/lib/go-1.14/src/runtime/panic.go:881 +0x60 fp=0x3fcc57f660 sp=0x3fcc57f630 pc=0x2aaaf05b70
runtime.runOpenDeferFrame(0x3fcc2aa780, 0x3fcc5b1400, 0x3fcc57f760)
 /usr/lib/go-1.14/src/runtime/panic.go:855 +0x360 fp=0x3fcc57f6e8 sp=0x3fcc57f660 pc=0x2aaaf059f0
runtime.Goexit()
 /usr/lib/go-1.14/src/runtime/panic.go:617 +0x1ec fp=0x3fcc57f760 sp=0x3fcc57f6e8 pc=0x2aaaf05024
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*C).stopNow(...)
 /<<PKGBUILDDIR>>/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/check.go:106
github.com/snapcore/snapd/vendor/gopkg.in/check%2ev1.(*C).Assert(0x3fcc3ceff0, 0x2aaba4fd60, 0x3fcc3c30c0, 0x2aabb7c160, 0x2aac15d510, 0x0, 0x0, 0x0)
 /<<PKGBUILDDIR>>/_build/src/github.com/snapcore/snapd/vendor/gopkg.in/check.v1/helpers.go:174 +0x94 fp=0x3fcc57f7c0 sp=0x3fcc57f760 pc=0x2aab517844
github.com/snapcore/snapd/overlord/snapstate_test.(*snapmgrTestSuite).settle(0x3fcc14c000, 0x3fcc3ceff0)
 /<<PKGBUILDDIR>>/_build/src/github.com/snapcore/snapd/overlord/snapstate/snapstate_test.go:87 +0xb0 fp=0x3fcc57f808 sp=0x3fcc57f7c0 pc=0x2aab7036e0
github.com/snapcore/snapd/overlord/snapstate_test.(*snapmgrTestSuite).testUpdateScenario(0x3fcc14c000, 0x3fcc3ceff0, 0x2aab7d1d59, 0x1d, 0x2aab7b7a40, 0x0, 0x2aab7c69a3, 0x13, 0x2aab7b7a40, 0x0, ...)
 /<<PKGBUILDDIR>>/_build/src/github.com/snapcore/snapd/overlord/snapstate/snapstate_test.go:8216 +0x644 fp=0x3fcc57fa30 sp=0x3fcc57f808 pc=0x2aab766c04
github.com/snapcore/snapd/overlord/snapstate_test.(*snapmgrTestSuite).TestUpdateScenarios(0x3fcc14c000, 0x3fcc3ceff0)
 /<<PKGBUILDDIR>>/_build/src/github.com/snapcore/snapd/overlord/snapstate/snapstate_test.go:8179 +0xf8 fp=0x3fcc57fbb0 sp=0x3fcc57fa30 pc=0x2aab766590
runtime.call32(0x3fcc4583c0, 0x3fcc00e628, 0x3fcc38c850)
 /usr/lib/go-1.14/src/runtime/asm_riscv64.s:486 ...

[Dimitri John Ledkov (xnox)]

somebody should checkout a riscv64 machine in testflinger, or use VM from https://people.ubuntu.com/~wgrant/riscv64/ to boot riscv64 and debug this issue.