user svc resource panics when service fails to start

jonathangold commented 5 years ago

Versions:

mgmt version (eg: mgmt --version): 0.0.15-65-g7cf1e4b
operating system/distribution (eg: uname -a): Linux vps 4.9.0-8-amd64 #1 SMP Debian 4.9.130-2 (2018-10-27) x86_64 GNU/Linux
golang version (eg: go version): go version go1.11.2 linux/amd64

Description:

The svc resource works fine unless session => true, in which case it panics (close of closed channel.)

svc "znc.service" {
    state => "running",
    session => true,
}

jon@vps:~$ mgmt run --lang svc.mcl --tmp-prefix
18:14:03 hello.go:46: This is: mgmt, version: 0.0.15-74-g3715cc7
18:14:03 hello.go:47: main: Start: 1544120043245760010
18:14:03 main.go:186: main: warning: working prefix directory is temporary!
18:14:03 main.go:186: main: working prefix is: /tmp/mgmt-vps-346817944
18:14:03 pgp.go:88: PGP: Created key: 070C0ABB
18:14:03 main.go:186: main: etcd: seeds: no seeds specified!
18:14:03 etcd.go:435: Etcd: Bootstrapping...
18:14:03 etcd.go:1463: Etcd: Nominated: vps=http://localhost:2380
18:14:03 etcd.go:1478: Etcd: StartServer(newCluster: true): vps=http://localhost:2380
18:14:03 etcd.go:1749: Etcd: StartServer: Starting server...
18:14:03 etcd.go:350: Etcd: Connect: Endpoints: []
18:14:03 etcd.go:364: Etcd: Connect: CtxError...
18:14:03 etcd.go:644: Etcd: CtxError: Reason: CtxDelayErr(1s): No endpoints available yet!
18:14:03 etcd.go:1756: Etcd: StartServer: Done starting server!
18:14:03 etcd.go:1774: Etcd: StartServer: Server running...
18:14:03 etcd.go:1501: Etcd: Addresses are: http://localhost:2379
18:14:04 etcd.go:348: Etcd: Connect: Endpoints: vps=http://localhost:2379
18:14:04 etcd.go:455: Etcd: Startup: Volunteering...
18:14:04 etcd.go:1669: Etcd: Ideal cluster size is now: 5
18:14:04 etcd.go:1022: Etcd: Set(/_mgmt/idealClusterSize): &{cluster_id:14841639068965178418 member_id:10276657743932975437 revision:4 raft_term:2  <nil>}
18:14:04 etcd.go:1263: Etcd: Members: List: [vps]
18:14:04 etcd.go:1286: Etcd: Leader: vps
18:14:04 etcd.go:1305: Etcd: Volunteers: [vps]
18:14:04 etcd.go:1309: Etcd: Quitters: []
18:14:04 etcd.go:1321: Etcd: Candidates: []
18:14:04 etcd.go:1263: Etcd: Members: List: [vps]
18:14:04 etcd.go:1286: Etcd: Leader: vps
18:14:04 etcd.go:1305: Etcd: Volunteers: [vps]
18:14:04 etcd.go:1309: Etcd: Quitters: []
18:14:04 etcd.go:1321: Etcd: Candidates: []
18:14:05 main.go:186: main: waiting...
18:14:05 main.go:186: main: waiting...
18:14:05 main.go:486: gapi: generating new graph...
18:14:05 main.go:486: gapi: swap!
18:14:05 main.go:486: gapi: lang: lexing/parsing...
18:14:05 main.go:186: main: running...
18:14:06 main.go:486: gapi: lang: interpolating...
18:14:06 main.go:486: gapi: lang: building scope...
18:14:06 main.go:486: gapi: lang: running type unification...
18:14:06 main.go:486: gapi: lang: building function graph...
18:14:06 main.go:486: gapi: lang: function engine initializing...
18:14:06 main.go:486: gapi: lang: function engine validating...
18:14:06 main.go:486: gapi: lang: function engine starting...
18:14:06 main.go:486: gapi: lang: stream...
18:14:06 main.go:486: gapi: lang: loop...
18:14:06 main.go:486: gapi: lang: funcs: func `str(running)` started
18:14:06 main.go:486: gapi: lang: funcs: func `str(running)` changed
18:14:06 main.go:486: gapi: lang: funcs: func `bool(true)` started
18:14:06 main.go:486: gapi: lang: funcs: func `bool(true)` changed
18:14:06 main.go:486: gapi: lang: funcs: func `str(znc.service)` started
18:14:06 main.go:486: gapi: lang: funcs: func `str(znc.service)` changed
18:14:06 main.go:486: gapi: lang: funcs: func `bool(true)` stopped
18:14:06 main.go:486: gapi: lang: funcs: func `str(running)` stopped
18:14:06 main.go:486: gapi: lang: funcs: func `str(znc.service)` stopped
18:14:06 main.go:486: gapi: generating new graph...
18:14:06 main.go:486: gapi: generating new graph...
18:14:06 main.go:486: gapi: lang: running interpret...
18:14:06 main.go:405: engine: autoedge: adding autoedges...
18:14:06 main.go:405: engine: autogroup: algorithm: wrappedGrouper: NonReachabilityGrouper...
18:14:06 main.go:186: main: commit...
18:14:06 main.go:405: engine: graph sync...
18:14:06 main.go:405: engine: Worker(svc[znc.service])
18:14:06 main.go:405: engine: Watch(svc[znc.service])
18:14:06 main.go:186: main: graph: Vertices(1), Edges(0)
18:14:06 main.go:186: main: waiting...
18:14:06 main.go:486: gapi: lang: running interpret...
18:14:06 main.go:405: engine: autoedge: adding autoedges...
18:14:06 main.go:405: engine: autogroup: algorithm: wrappedGrouper: NonReachabilityGrouper...
18:14:06 main.go:486: gapi: generating new graph...
18:14:06 main.go:405: engine: svc[znc.service]: CheckApply(true)
18:14:06 main.go:405: engine: svc[znc.service]: resource: failed to get property: Process org.freedesktop.systemd1 exited with status 1
18:14:06 main.go:405: engine: svc[znc.service]: resource: waiting fo service
18:14:06 main.go:405: engine: svc[znc.service]: CheckApply(true): Return(false, Process org.freedesktop.systemd1 exited with status 1
failed to get load state
github.com/purpleidea/mgmt/engine/resources.(*SvcRes).CheckApply
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/resources/svc.go:250
github.com/purpleidea/mgmt/engine/graph.(*Engine).Process
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/graph/actions.go:160
github.com/purpleidea/mgmt/engine/graph.(*Engine).Worker
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/graph/actions.go:441
github.com/purpleidea/mgmt/engine/graph.(*Engine).Start.func1
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/graph/engine.go:268
runtime.goexit
    /usr/lib/golang/src/runtime/asm_amd64.s:1333)
18:14:06 main.go:405: engine: svc[znc.service]: exit event...
18:14:06 main.go:405: engine: Watch(svc[znc.service]): Exited(unhandled event: 0)
18:14:06 main.go:405: engine: Worker(svc[znc.service]): Exited(Process org.freedesktop.systemd1 exited with status 1
failed to get load state
github.com/purpleidea/mgmt/engine/resources.(*SvcRes).CheckApply
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/resources/svc.go:250
github.com/purpleidea/mgmt/engine/graph.(*Engine).Process
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/graph/actions.go:160
github.com/purpleidea/mgmt/engine/graph.(*Engine).Worker
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/graph/actions.go:441
github.com/purpleidea/mgmt/engine/graph.(*Engine).Start.func1
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/graph/engine.go:268
runtime.goexit
    /usr/lib/golang/src/runtime/asm_amd64.s:1333
error during Process()
github.com/purpleidea/mgmt/engine/graph.(*Engine).Process
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/graph/actions.go:240
github.com/purpleidea/mgmt/engine/graph.(*Engine).Worker
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/graph/actions.go:441
github.com/purpleidea/mgmt/engine/graph.(*Engine).Start.func1
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/graph/engine.go:268
runtime.goexit
    /usr/lib/golang/src/runtime/asm_amd64.s:1333)
18:14:06 main.go:186: main: commit...
18:14:06 main.go:405: engine: graph sync...
18:14:06 main.go:186: main: graph: Vertices(1), Edges(0)
18:14:06 main.go:186: main: waiting...
18:14:06 main.go:486: gapi: lang: running interpret...
18:14:06 main.go:405: engine: autoedge: adding autoedges...
18:14:06 main.go:405: engine: autogroup: algorithm: wrappedGrouper: NonReachabilityGrouper...
18:14:06 main.go:405: engine: Worker(svc[znc.service])
18:14:06 main.go:405: engine: Watch(svc[znc.service])
18:14:06 main.go:186: main: commit...
18:14:06 main.go:405: engine: graph sync...
18:14:06 main.go:186: main: graph: Vertices(1), Edges(0)
18:14:06 main.go:186: main: waiting...
panic: close of closed channel
    panic: close of closed channel

goroutine 235 [running]:
github.com/purpleidea/mgmt/engine/graph.(*State).Init.func1(0xc000527c20, 0xc000493c20)
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/graph/state.go:131 +0x36
github.com/purpleidea/mgmt/engine/resources.(*SvcRes).Watch(0xc00052d680, 0x0, 0x0)
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/resources/svc.go:114 +0x1bb
github.com/purpleidea/mgmt/engine/graph.(*Engine).Worker.func1(0xc0002406e0, 0x7fcc6a15c3f0, 0xc00052d680, 0x1b9f760, 0xc00052d680)
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/graph/actions.go:303 +0xbf0
created by github.com/purpleidea/mgmt/engine/graph.(*Engine).Worker
    /home/jon/go/src/github.com/purpleidea/mgmt/engine/graph/actions.go:262 +0x392

jonathangold commented 5 years ago

I might have a go at this one in a bit.

jonathangold commented 5 years ago

~~I think the issue's on my end. Closing for now.~~ Fixed my issue. Still panics.

purpleidea commented 5 years ago

It should never panic unless something is really wrong (eg: hardware error)

Maybe something changed with go-systemd package?

I'd try with an older version of that for fun (one where I made a commit perhaps) and then we write tests and fix bugs :/

purpleidea commented 5 years ago

But we (I?) have to fix that engine bug panic to make sure none of these are related to that.

jonathangold commented 5 years ago

This is NOT happening on my fedora box. It must be something with debian and/or google cloud. I'll post the fix here if and when I find it.

jonathangold commented 5 years ago

So the issue was on my end (the unit was failing to start,) but that should result in an error, not a panic.

purpleidea / mgmt

user svc resource panics when service fails to start #412

Versions:

Description: