Panic in snapshot docker environment

[andrewstucki]

I haven't dug into the stack trace or the package-registry project/container much, but I just got this panic after rebuilding assets which resulted in me having to re-spin up my docker environment again (which, with kibana, can take awhile):

package-registry_1  | fatal error: sync: unlock of unlocked mutex
package-registry_1  |
package-registry_1  | goroutine 189 [running]:
package-registry_1  | runtime.throw(0x8b7f20, 0x1e)
package-registry_1  | 	/usr/local/go/src/runtime/panic.go:1116 +0x72 fp=0xc000b63a78 sp=0xc000b63a48 pc=0x434b42
package-registry_1  | sync.throw(0x8b7f20, 0x1e)
package-registry_1  | 	/usr/local/go/src/runtime/panic.go:1102 +0x35 fp=0xc000b63a98 sp=0xc000b63a78 pc=0x434ac5
package-registry_1  | sync.(*Mutex).unlockSlow(0xc0003bb708, 0xc0ffffffff)
package-registry_1  | 	/usr/local/go/src/sync/mutex.go:196 +0xd6 fp=0xc000b63ac0 sp=0xc000b63a98 pc=0x47cfe6
package-registry_1  | sync.(*Mutex).Unlock(0xc0003bb708)
package-registry_1  | 	/usr/local/go/src/sync/mutex.go:190 +0x48 fp=0xc000b63ae0 sp=0xc000b63ac0 pc=0x47cef8
package-registry_1  | runtime.call32(0x0, 0x8d1938, 0xc0002aa6d8, 0x800000008)
package-registry_1  | 	/usr/local/go/src/runtime/asm_amd64.s:539 +0x3b fp=0xc000b63b10 sp=0xc000b63ae0 pc=0x4627db
package-registry_1  | runtime.reflectcallSave(0xc000b63c40, 0x8d1938, 0xc0002aa6d8, 0x8)
package-registry_1  | 	/usr/local/go/src/runtime/panic.go:881 +0x58 fp=0xc000b63b40 sp=0xc000b63b10 pc=0x434248
package-registry_1  | runtime.runOpenDeferFrame(0xc000414c00, 0xc0002aa690, 0xc000b63c88)
package-registry_1  | 	/usr/local/go/src/runtime/panic.go:855 +0x2b9 fp=0xc000b63bd0 sp=0xc000b63b40 pc=0x434109
package-registry_1  | panic(0x83c9c0, 0xc0003a1e30)
package-registry_1  | 	/usr/local/go/src/runtime/panic.go:969 +0x166 fp=0xc000b63c88 sp=0xc000b63bd0 pc=0x434456
package-registry_1  | runtime.panicdottypeE(...)
package-registry_1  | 	/usr/local/go/src/runtime/iface.go:260
package-registry_1  | runtime.panicdottypeI(0x951700, 0x8451e0, 0x83ec80)
package-registry_1  | 	/usr/local/go/src/runtime/iface.go:270 +0xcb fp=0xc000b63cb0 sp=0xc000b63c88 pc=0x40b73b
package-registry_1  | github.com/radovskyb/watcher.(*Watcher).retrieveFileList(0xc000394400, 0x0)
package-registry_1  | 	/go/pkg/mod/github.com/radovskyb/[email protected]/watcher.go:500 +0x6c6 fp=0xc000b63e20 sp=0xc000b63cb0 pc=0x7bbdd6
package-registry_1  | github.com/radovskyb/watcher.(*Watcher).Start(0xc000394400, 0x77359400, 0x0, 0x40)
package-registry_1  | 	/go/pkg/mod/github.com/radovskyb/[email protected]/watcher.go:563 +0x38f fp=0xc000b63fc0 sp=0xc000b63e20 pc=0x7bc18f
package-registry_1  | runtime.goexit()
package-registry_1  | 	/usr/local/go/src/runtime/asm_amd64.s:1373 +0x1 fp=0xc000b63fc8 sp=0xc000b63fc0 pc=0x464531
package-registry_1  | created by github.com/elastic/package-registry/util.MustUsePackageWatcher
package-registry_1  | 	/home/package-registry/util/package_watcher.go:41 +0x225
package-registry_1  |
package-registry_1  | goroutine 1 [chan receive, 18 minutes]:
package-registry_1  | main.main()
package-registry_1  | 	/home/package-registry/main.go:101 +0x37b
package-registry_1  |
package-registry_1  | goroutine 1708 [chan send, 5 minutes]:
package-registry_1  | github.com/radovskyb/watcher.(*Watcher).Start.func1(0xc000394400, 0xc0001c61e0, 0xc000766120, 0xc0007e3aa0, 0xc000766000)
package-registry_1  | 	/go/pkg/mod/github.com/radovskyb/[email protected]/watcher.go:571 +0x61
package-registry_1  | created by github.com/radovskyb/watcher.(*Watcher).Start
package-registry_1  | 	/go/pkg/mod/github.com/radovskyb/[email protected]/watcher.go:569 +0x404
package-registry_1  |
package-registry_1  | goroutine 1672 [chan send, 6 minutes]:
package-registry_1  | github.com/radovskyb/watcher.(*Watcher).Start.func1(0xc000394400, 0xc0003ec000, 0xc00032e2a0, 0xc0008ee060, 0xc00032e0c0)
package-registry_1  | 	/go/pkg/mod/github.com/radovskyb/[email protected]/watcher.go:571 +0x61
package-registry_1  | created by github.com/radovskyb/watcher.(*Watcher).Start
package-registry_1  | 	/go/pkg/mod/github.com/radovskyb/[email protected]/watcher.go:569 +0x404
package-registry_1  |
package-registry_1  | goroutine 192 [syscall, 18 minutes]:
package-registry_1  | os/signal.signal_recv(0x0)
package-registry_1  | 	/usr/local/go/src/runtime/sigqueue.go:147 +0x9c
package-registry_1  | os/signal.loop()
package-registry_1  | 	/usr/local/go/src/os/signal/signal_unix.go:23 +0x22
package-registry_1  | created by os/signal.Notify.func1
package-registry_1  | 	/usr/local/go/src/os/signal/signal.go:127 +0x44
package-registry_1  |
package-registry_1  | goroutine 191 [IO wait]:
package-registry_1  | internal/poll.runtime_pollWait(0x7fbbed03f230, 0x72, 0x0)
package-registry_1  | 	/usr/local/go/src/runtime/netpoll.go:203 +0x55
package-registry_1  | internal/poll.(*pollDesc).wait(0xc000394398, 0x72, 0x0, 0x0, 0x8ad345)
package-registry_1  | 	/usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0x45
package-registry_1  | internal/poll.(*pollDesc).waitRead(...)
package-registry_1  | 	/usr/local/go/src/internal/poll/fd_poll_runtime.go:92
package-registry_1  | internal/poll.(*FD).Accept(0xc000394380, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
package-registry_1  | 	/usr/local/go/src/internal/poll/fd_unix.go:384 +0x1d4
package-registry_1  | net.(*netFD).accept(0xc000394380, 0x3450abf78a047136, 0xf5527a514322d615, 0x3450abf78a047136)
package-registry_1  | 	/usr/local/go/src/net/fd_unix.go:238 +0x42
package-registry_1  | net.(*TCPListener).accept(0xc00000f5e0, 0x5f175456, 0xc000046de0, 0x4ba346)
package-registry_1  | 	/usr/local/go/src/net/tcpsock_posix.go:139 +0x32
package-registry_1  | net.(*TCPListener).Accept(0xc00000f5e0, 0xc000046e30, 0x18, 0xc000415680, 0x6c2f6c)
package-registry_1  | 	/usr/local/go/src/net/tcpsock.go:261 +0x64
package-registry_1  | net/http.(*Server).Serve(0xc0007e0000, 0x9584a0, 0xc00000f5e0, 0x0, 0x0)
package-registry_1  | 	/usr/local/go/src/net/http/server.go:2901 +0x25d
package-registry_1  | net/http.(*Server).ListenAndServe(0xc0007e0000, 0xc00035d458, 0x2)
package-registry_1  | 	/usr/local/go/src/net/http/server.go:2830 +0xb7
package-registry_1  | main.main.func1(0xc0007e0000)
package-registry_1  | 	/home/package-registry/main.go:93 +0x2f
package-registry_1  | created by main.main
package-registry_1  | 	/home/package-registry/main.go:92 +0x2ca
package-registry_1  |
package-registry_1  | goroutine 190 [runnable]:
package-registry_1  | syscall.Syscall6(0x101, 0xffffffffffffff9c, 0xc000d92230, 0x80000, 0x0, 0x0, 0x0, 0x3, 0x80000, 0x0)
package-registry_1  | 	/usr/local/go/src/syscall/asm_linux_amd64.s:41 +0x5
package-registry_1  | syscall.openat(0xffffffffffffff9c, 0xc000d92150, 0x65, 0x80000, 0x0, 0x203000, 0x203000, 0xc000498c10)
package-registry_1  | 	/usr/local/go/src/syscall/zsyscall_linux_amd64.go:68 +0xbb
package-registry_1  | syscall.Open(...)
package-registry_1  | 	/usr/local/go/src/syscall/syscall_linux.go:138
package-registry_1  | os.openFileNolog(0xc000d92150, 0x65, 0x0, 0xc000000000, 0x43e8d8, 0xc000415800, 0x200000003)
package-registry_1  | 	/usr/local/go/src/os/file_unix.go:200 +0x8f
package-registry_1  | os.OpenFile(0xc000d92150, 0x65, 0x0, 0x0, 0xffffffffffffff9c, 0xc000d921c0, 0xc0002e9488)
package-registry_1  | 	/usr/local/go/src/os/file.go:307 +0x63
package-registry_1  | os.Open(...)
package-registry_1  | 	/usr/local/go/src/os/file.go:287
package-registry_1  | io/ioutil.ReadFile(0xc000d92150, 0x65, 0x0, 0x0, 0x0, 0x0, 0x0)
package-registry_1  | 	/usr/local/go/src/io/ioutil/ioutil.go:53 +0x77
package-registry_1  | github.com/elastic/package-registry/util.validateIngestPipelineFile(0xc000d92150, 0x65, 0x950f40, 0xc0000920e0)
package-registry_1  | 	/home/package-registry/util/dataset.go:240 +0x4d
package-registry_1  | github.com/elastic/package-registry/util.(*Dataset).Validate(0xc0001288c0, 0x3b, 0xc0005ebc80)
package-registry_1  | 	/home/package-registry/util/dataset.go:215 +0x6ec
package-registry_1  | github.com/elastic/package-registry/util.(*Package).ValidateDatasets(0xc0005ebc80, 0x0, 0x0)
package-registry_1  | 	/home/package-registry/util/package.go:452 +0x1e5
package-registry_1  | github.com/elastic/package-registry/util.(*Package).Validate(0xc0005ebc80, 0x884340, 0xc0005ebc80)
package-registry_1  | 	/home/package-registry/util/package.go:360 +0x2fb
package-registry_1  | github.com/elastic/go-ucfg.tryValidate(0x89b2a0, 0xc0005ebc80, 0x199, 0x0, 0x0)
package-registry_1  | 	/go/pkg/mod/github.com/elastic/[email protected]/validator.go:127 +0x159
package-registry_1  | github.com/elastic/go-ucfg.reifyStruct(0xc0002a4120, 0x89b2a0, 0xc0005eb680, 0x199, 0xc000c2f110, 0x0, 0x0)
package-registry_1  | 	/go/pkg/mod/github.com/elastic/[email protected]/reify.go:299 +0x22a
package-registry_1  | github.com/elastic/go-ucfg.reifyInto(0xc0002a4120, 0x884340, 0xc0005eb680, 0x16, 0xc000c2f110, 0xc0002b96b8, 0x796a8d)
package-registry_1  | 	/go/pkg/mod/github.com/elastic/[email protected]/reify.go:177 +0x40c
package-registry_1  | github.com/elastic/go-ucfg.(*Config).Unpack(0xc000c2f110, 0x884340, 0xc0005eb680, 0xc0002b98c8, 0x1, 0x1, 0x0, 0x0)
package-registry_1  | 	/go/pkg/mod/github.com/elastic/[email protected]/reify.go:155 +0xf5
package-registry_1  | github.com/elastic/package-registry/util.NewPackage(0xc000ad58c0, 0x2c, 0x3, 0xc00071e400, 0x30)
package-registry_1  | 	/home/package-registry/util/package.go:151 +0x20f
package-registry_1  | github.com/elastic/package-registry/util.getPackagesFromFilesystem(0xc0001c62d0, 0x3, 0x3, 0x0, 0x1, 0x40, 0x0, 0x0)
package-registry_1  | 	/home/package-registry/util/packages.go:45 +0xf1
package-registry_1  | github.com/elastic/package-registry/util.MustUsePackageWatcher.func1(0xc0001c62d0, 0x3, 0x3, 0xc0001a7b20)
package-registry_1  | 	/home/package-registry/util/package_watcher.go:54 +0x149
package-registry_1  | created by github.com/elastic/package-registry/util.MustUsePackageWatcher
package-registry_1  | 	/home/package-registry/util/package_watcher.go:43 +0x26e
package-registry_1  |
package-registry_1  | goroutine 1991 [chan send, 5 minutes]:
package-registry_1  | github.com/radovskyb/watcher.(*Watcher).Start.func1(0xc000394400, 0xc000448000, 0xc000a26cc0, 0xc00084e4e0, 0xc000a26c00)
package-registry_1  | 	/go/pkg/mod/github.com/radovskyb/[email protected]/watcher.go:571 +0x61
package-registry_1  | created by github.com/radovskyb/watcher.(*Watcher).Start
package-registry_1  | 	/go/pkg/mod/github.com/radovskyb/[email protected]/watcher.go:569 +0x404
package-registry_1  |
package-registry_1  | goroutine 3091 [chan send]:
package-registry_1  | github.com/radovskyb/watcher.(*Watcher).Start.func1(0xc000394400, 0xc000c2e4b0, 0xc000022480, 0xc000d3f9e0, 0xc000022360)
package-registry_1  | 	/go/pkg/mod/github.com/radovskyb/[email protected]/watcher.go:571 +0x61
package-registry_1  | created by github.com/radovskyb/watcher.(*Watcher).Start
package-registry_1  | 	/go/pkg/mod/github.com/radovskyb/[email protected]/watcher.go:569 +0x404

It appears to be trying to unlock a mutex that's not currently locked. While we should fix the bug in the underlying program, for now we should also set the docker-compose manifest to have restart: always for at least this container.

[mtojek]

I suspect this is the root cause (and the fix) for this problem: radovskyb/watcher#96 . Unfortunately it's not maintained anymore, I'm afraid we need to fork it.

I appears to be only in the development mode (in config: dev_mode: true) and should be fixed on the package-registry side.

[mtojek]

I decided to get rid of the package watching over docker volumes (it's really slow). An alternative approach here: #185