mgmt does not keep mariadb running on CentOS 7

[xet7]

Versions:

• mgmt version (eg: mgmt --version):

mgmt version 0.0.15-3-gfdd698d

• operating system/distribution (eg: uname -a):

CentOS 7, running on VM on top of OpenStack

Linux subdomain.example.com 3.10.0-693.21.1.el7.x86_64 #1 SMP Wed Mar 7 19:03:37 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

• golang version (eg: go version):

go1.9.1.linux-amd64 https://github.com/purpleidea/mgmt/blob/master/docker/Dockerfile.build with added line ENV GOTAGS='noaugeas novirt' built with: docker build - < Dockerfile.build

That mgmt binary itself does run on CentOS 6 and 7, Debian Sid and Ubuntu 17.10. It was tested with copying binary to those, and run ./mgmt so it did show text output on all of those.

Description:

services-running.mcl:

svc "mariadb" {
    state => "running",
}
svc "php-fpm" {
    state => "running",
}
svc "nginx" {
    state => "running",
}

This is run as root with command:

./mgmt run --tmp-prefix --lang services-running.mcl

Expected result

Keep mariadb running: when in another bash prompt is given command systemctl stop mariadb, mgmt should start mariadb again.

For nginx and php, mgmt starts them. But not for mariadb.

What happens instead

1) mariadb is is stopped with systemctl stop mariadb

2) mgmt is started with ./mgmt run --tmp-prefix --lang services-running.mcl and mgmt starts mariadb service.

./mgmt run --tmp-prefix --lang services-running.mcl
13:28:26 hello.go:46: This is: mgmt, version: 0.0.15-3-gfdd698d
13:28:26 hello.go:47: Main: Start: 1520681306753890290
13:28:26 main.go:230: Main: Warning: Working prefix directory is temporary!
13:28:26 main.go:236: Main: Working prefix is: /tmp/mgmt-subdomain.example.com-706764134
13:28:27 pgp.go:88: PGP: Created key: 2959CD2A
13:28:27 main.go:329: Main: Seeds: No seeds specified!
13:28:27 etcd.go:420: Etcd: Bootstrapping...
13:28:27 etcd.go:1448: Etcd: Nominated: subdomain.example.com=http://127.0.0.1:2380
13:28:27 etcd.go:1463: Etcd: StartServer(newCluster: true): subdomain.example.com=http://127.0.0.1:2380
13:28:27 etcd.go:335: Etcd: Connect: Endpoints: []
13:28:27 etcd.go:349: Etcd: Connect: CtxError...
13:28:27 etcd.go:629: Etcd: CtxError: Reason: CtxDelayErr(1s): No endpoints available yet!
13:28:27 etcd.go:1734: Etcd: StartServer: Starting server...
13:28:28 etcd.go:1741: Etcd: StartServer: Done starting server!
13:28:28 etcd.go:1759: Etcd: StartServer: Server running...
13:28:28 etcd.go:1486: Etcd: Addresses are: http://127.0.0.1:2379
13:28:28 etcd.go:333: Etcd: Connect: Endpoints: subdomain.example.com=http://127.0.0.1:2379
13:28:28 etcd.go:1806: Etcd: ApplyDeltaEvents: Event(PUT): subdomain.example.com
13:28:28 etcd.go:1448: Etcd: Nominated: subdomain.example.com=http://127.0.0.1:2380
13:28:28 etcd.go:440: Etcd: Startup: Volunteering...
13:28:28 etcd.go:1654: Etcd: Ideal cluster size is now: 5
13:28:28 etcd.go:1007: Etcd: Set(/_mgmt/idealClusterSize): &{cluster_id:2037210783374497686 member_id:13195394291058371180 revision:4 raft_term:2  <nil>}
13:28:28 etcd.go:1248: Etcd: Members: List: [subdomain.example.com]
13:28:28 etcd.go:1271: Etcd: Leader: subdomain.example.com
13:28:28 etcd.go:1290: Etcd: Volunteers: [subdomain.example.com]
13:28:28 etcd.go:1294: Etcd: Quitters: []
13:28:28 etcd.go:1306: Etcd: Candidates: []
13:28:28 etcd.go:1248: Etcd: Members: List: [subdomain.example.com]
13:28:28 etcd.go:1271: Etcd: Leader: subdomain.example.com
13:28:28 etcd.go:1290: Etcd: Volunteers: [subdomain.example.com]
13:28:28 etcd.go:1294: Etcd: Quitters: []
13:28:28 etcd.go:1306: Etcd: Candidates: []
13:28:29 main.go:718: Main: Remotes: Run: Ready!
13:28:29 main.go:428: Main: Waiting...
13:28:29 main.go:428: Main: Waiting...
13:28:29 gapi.go:212: lang: Generating new graph...
13:28:29 gapi.go:216: lang: Swap!
13:28:29 main.go:805: Main: Running...
13:28:29 lang.go:82: lang: Lexing/Parsing...
13:28:29 lang.go:97: lang: Interpolating...
13:28:29 lang.go:114: lang: Building Scope...
13:28:29 lang.go:126: lang: Running Type Unification...
13:28:29 lang.go:131: lang: Building Function Graph...
13:28:29 lang.go:173: lang: Function Engine Initializing...
13:28:29 lang.go:178: lang: Function Engine Validating...
13:28:29 lang.go:183: lang: Function Engine Starting...
13:28:29 lang.go:192: lang: Stream...
13:28:29 lang.go:196: lang: Loop...
13:28:29 lang.go:168: lang: funcs: func `str(php-fpm)` started
13:28:29 lang.go:168: lang: funcs: func `str(mariadb)` started
13:28:29 lang.go:168: lang: funcs: func `str(nginx)` started
13:28:29 lang.go:168: lang: funcs: func `str(mariadb)` changed
13:28:29 lang.go:168: lang: funcs: func `str(nginx)` changed
13:28:29 lang.go:168: lang: funcs: func `str(mariadb)` stopped
13:28:29 lang.go:168: lang: funcs: func `str(running)` started
13:28:29 lang.go:168: lang: funcs: func `str(nginx)` stopped
13:28:29 lang.go:168: lang: funcs: func `str(running)` started
13:28:29 lang.go:168: lang: funcs: func `str(running)` changed
13:28:29 gapi.go:212: lang: Generating new graph...
13:28:29 lang.go:168: lang: funcs: func `str(running)` started
13:28:29 lang.go:168: lang: funcs: func `str(running)` stopped
13:28:29 lang.go:168: lang: funcs: func `str(running)` changed
13:28:29 lang.go:168: lang: funcs: func `str(running)` stopped
13:28:29 gapi.go:212: lang: Generating new graph...
13:28:29 lang.go:168: lang: funcs: func `str(php-fpm)` changed
13:28:29 lang.go:168: lang: funcs: func `str(php-fpm)` stopped
13:28:29 lang.go:249: lang: Running interpret...
13:28:29 lang.go:168: lang: funcs: func `str(running)` changed
13:28:29 lang.go:168: lang: funcs: func `str(running)` stopped
13:28:29 main.go:581: Main: GraphSync...
13:28:29 autoedge.go:92: Compile: Adding AutoEdges...
13:28:29 autogroup.go:352: Compile: Grouping: Algorithm: NonReachabilityGrouper...
13:28:29 mgraph.go:99: State: 0 -> 1
13:28:29 mgraph.go:162: svc[mariadb]: Started
13:28:29 mgraph.go:162: svc[php-fpm]: Started
13:28:29 svc.go:167: Watching: mariadb.service
13:28:29 svc.go:269: svc[mariadb]: Apply
13:28:29 mgraph.go:162: svc[nginx]: Started
13:28:29 svc.go:171: Svc event: map[mariadb.service:0xc420704c10]
13:28:29 svc.go:180: Svc[mariadb.service]->Stopped
13:28:29 svc.go:167: Watching: php-fpm.service
13:28:29 svc.go:167: Watching: mariadb.service
13:28:29 svc.go:171: Svc event: map[php-fpm.service:0xc420d9c0d8]
13:28:29 svc.go:178: Svc[php-fpm.service]->Started
13:28:29 svc.go:167: Watching: php-fpm.service
13:28:29 mgraph.go:182: State: 1 -> 2
13:28:29 main.go:652: Main: Graph: Vertices(3), Edges(0)
13:28:29 main.go:428: Main: Waiting...
13:28:29 gapi.go:212: lang: Generating new graph...
13:28:29 mgraph.go:188: State: 2 -> 3
13:28:29 svc.go:167: Watching: nginx.service
13:28:31 mgraph.go:198: State: 3 -> 4
13:28:31 lang.go:249: lang: Running interpret...
13:28:31 main.go:581: Main: GraphSync...
13:28:31 autoedge.go:92: Compile: Adding AutoEdges...
13:28:31 autogroup.go:352: Compile: Grouping: Algorithm: NonReachabilityGrouper...
13:28:31 mgraph.go:99: State: 4 -> 1
13:28:31 mgraph.go:182: State: 1 -> 2
13:28:31 main.go:652: Main: Graph: Vertices(3), Edges(0)
13:28:31 main.go:428: Main: Waiting...
13:28:31 gapi.go:212: lang: Generating new graph...
13:28:31 mgraph.go:188: State: 2 -> 3
13:28:31 svc.go:167: Watching: nginx.service
13:28:31 svc.go:171: Svc event: map[nginx.service:0xc420441460]
13:28:31 svc.go:178: Svc[nginx.service]->Started
13:28:31 svc.go:167: Watching: php-fpm.service
13:28:31 svc.go:167: Watching: mariadb.service
13:28:31 svc.go:171: Svc event: map[mariadb.service:0xc4206fac10]
13:28:31 actions.go:625: svc[mariadb]: Watch errored: Unknown svc state: activating
13:28:31 mgraph.go:164: svc[mariadb]: Exited with failure: Permanent watch error: Unknown svc state: activating
13:28:31 svc.go:167: Watching: nginx.service

3) mariadb is stopped with command systemctl stop mariadb. There is no output in mgmt, mgmt does not start mariadb again.

4) nginx is stopped with command systemctl stop nginx. mgmt starts it again.

13:38:51 svc.go:171: Svc event: map[nginx.service:0xc4210c5460]
13:38:51 svc.go:180: Svc[nginx.service]->Stopped
13:38:51 svc.go:167: Watching: nginx.service
13:38:51 svc.go:269: svc[nginx]: Apply
13:38:52 svc.go:171: Svc event: map[nginx.service:0xc42065f460]
13:38:52 svc.go:178: Svc[nginx.service]->Started
13:38:52 svc.go:167: Watching: nginx.service

5) php-fpm is stopped with command systemctl stop php-fpm. mgmt starts it again.

13:41:15 svc.go:171: Svc event: map[php-fpm.service:0xc4206600d8]
13:41:15 svc.go:180: Svc[php-fpm.service]->Stopped
13:41:15 svc.go:167: Watching: php-fpm.service
13:41:15 svc.go:269: svc[php-fpm]: Apply
13:41:16 svc.go:171: Svc event: map[php-fpm.service:0xc4206760d8]
13:41:16 svc.go:178: Svc[php-fpm.service]->Started
13:41:16 svc.go:167: Watching: php-fpm.service

6) mariadb is started with command systemctl start mariadb. There is no text output in mgmt.

7) mariadb is stopped with command systemctl stop mariadb. There is no text output in mgmt.

8) mariadb is started with command systemctl start mariadb. There is no text output in mgmt.

9) mgmt is stopped with Ctrl-c. mgmt gives this text, and does not exit immediately:

^C13:45:15 cli.go:154: Interrupted by ^C
13:45:15 main.go:809: Main: Destroy...

10) I use command kill -9 12592 to force mgmt to exit.

11) When I try with mgmt running using kill command to kill mariadb with kill -9 process-id, mariadb gets new process id and keeps running. There is no output in mgmt.

[purpleidea]

13:28:31 actions.go:625: svc[mariadb]: Watch errored: Unknown svc state: activating

You've found another previously unknown state that we don't yet handle. This commit: https://github.com/purpleidea/mgmt/commit/fdd698dadea7061c119ebf612972546ebd630fab#diff-8bce8caa5fe7da7642f1fe04b8589616R185 was just recently added to fix a similar issue with "deactivating".

Would you like to write the patch to add "activating" ? It will get you some free internet points :) If not, no problem, it's an easy fix and I'm happy to patch it for you.

[xet7]

@purpleidea

Cool, of course I'll try to do my first pull request to mgmt !! Just a moment...

BTW selinux is already disabled:

$ cat /etc/sysconfig/selinux
# This file controls the state of SELinux on the system.
# SELINUX= can take one of these three values:
#     enforcing - SELinux security policy is enforced.
#     permissive - SELinux prints warnings instead of enforcing.
#     disabled - No SELinux policy is loaded.
SELINUX=disabled
# SELINUXTYPE= can take one of three two values:
#     targeted - Targeted processes are protected,
#     minimum - Modification of targeted policy. Only selected processes are protected. 
#     mls - Multi Level Security protection.
SELINUXTYPE=targeted

[purpleidea]

@xet7

Cool, of course I'll try to do my first pull request to mgmt !! Just a moment...

Great! Some tips about some of our CI tests (and how to pass them on your first go) are visible here: https://github.com/purpleidea/mgmt/blob/master/.github/PULL_REQUEST_TEMPLATE.md

BTW selinux is already disabled

Based on the logs, once this is patched (two lines) I don't think you'll have this problem anymore, assuming there isn't an additional problem being masked under this.

Thanks!

[xet7]

@purpleidea

After those "deactivating" and "activating", now I got additional problem, when I run sudo systemctl stop mariadb:

$ ./mgmt run --tmp-prefix --lang services-running.mcl
11:21:25 hello.go:46: This is: mgmt, version: 97c11c1
11:21:25 hello.go:47: Main: Start: 1520846485099067222
11:21:25 main.go:201: Main: Warning: Working prefix directory is temporary!
11:21:25 main.go:207: Main: Working prefix is: /tmp/mgmt-subdomain.example.com-582675554
11:21:25 pgp.go:88: PGP: Created key: 794D6AE8
11:21:25 main.go:300: Main: Seeds: No seeds specified!
11:21:25 etcd.go:420: Etcd: Bootstrapping...
11:21:25 etcd.go:1448: Etcd: Nominated: subdomain.example.com=http://127.0.0.1:2380
11:21:25 etcd.go:1463: Etcd: StartServer(newCluster: true): subdomain.example.com=http://127.0.0.1:2380
11:21:25 etcd.go:335: Etcd: Connect: Endpoints: []
11:21:25 etcd.go:349: Etcd: Connect: CtxError...
11:21:25 etcd.go:1734: Etcd: StartServer: Starting server...
11:21:25 etcd.go:629: Etcd: CtxError: Reason: CtxDelayErr(1s): No endpoints available yet!
11:21:26 etcd.go:1741: Etcd: StartServer: Done starting server!
11:21:26 etcd.go:1759: Etcd: StartServer: Server running...
11:21:26 etcd.go:1486: Etcd: Addresses are: http://127.0.0.1:2379
11:21:26 etcd.go:333: Etcd: Connect: Endpoints: subdomain.example.com=http://127.0.0.1:2379
11:21:26 etcd.go:1806: Etcd: ApplyDeltaEvents: Event(PUT): subdomain.example.com
11:21:26 etcd.go:1448: Etcd: Nominated: subdomain.example.com=http://127.0.0.1:2380
11:21:26 etcd.go:440: Etcd: Startup: Volunteering...
11:21:26 etcd.go:1654: Etcd: Ideal cluster size is now: 5
11:21:26 etcd.go:1007: Etcd: Set(/_mgmt/idealClusterSize): &{cluster_id:2037210783374497686 member_id:13195394291058371180 revision:4 raft_term:2  <nil>}
11:21:26 etcd.go:1248: Etcd: Members: List: [subdomain.example.com]
11:21:26 etcd.go:1271: Etcd: Leader: subdomain.example.com
11:21:26 etcd.go:1290: Etcd: Volunteers: [subdomain.example.com]
11:21:26 etcd.go:1294: Etcd: Quitters: []
11:21:26 etcd.go:1306: Etcd: Candidates: []
11:21:26 etcd.go:1248: Etcd: Members: List: [subdomain.example.com]
11:21:26 etcd.go:1271: Etcd: Leader: subdomain.example.com
11:21:26 etcd.go:1290: Etcd: Volunteers: [subdomain.example.com]
11:21:26 etcd.go:1294: Etcd: Quitters: []
11:21:26 etcd.go:1306: Etcd: Candidates: []
11:21:27 main.go:399: Main: Waiting...
11:21:27 main.go:399: Main: Waiting...
11:21:27 main.go:720: Main: Running...
11:21:27 gapi.go:209: lang: Generating new graph...
11:21:27 gapi.go:213: lang: Swap!
11:21:27 lang.go:82: lang: Lexing/Parsing...
11:21:27 lang.go:97: lang: Interpolating...
11:21:27 lang.go:114: lang: Building Scope...
11:21:27 lang.go:126: lang: Running Type Unification...
11:21:27 lang.go:131: lang: Building Function Graph...
11:21:27 lang.go:173: lang: Function Engine Initializing...
11:21:27 lang.go:178: lang: Function Engine Validating...
11:21:27 lang.go:183: lang: Function Engine Starting...
11:21:27 lang.go:192: lang: Stream...
11:21:27 lang.go:196: lang: Loop...
11:21:27 lang.go:168: lang: funcs: func `str(nginx)` started
11:21:27 lang.go:168: lang: funcs: func `str(php-fpm)` started
11:21:27 lang.go:168: lang: funcs: func `str(mariadb)` started
11:21:27 lang.go:168: lang: funcs: func `str(running)` started
11:21:27 lang.go:168: lang: funcs: func `str(running)` changed
11:21:27 lang.go:168: lang: funcs: func `str(running)` stopped
11:21:27 gapi.go:209: lang: Generating new graph...
11:21:27 lang.go:249: lang: Running interpret...
11:21:27 main.go:552: Main: GraphSync...
11:21:27 lang.go:168: lang: funcs: func `str(php-fpm)` changed
11:21:27 lang.go:168: lang: funcs: func `str(php-fpm)` stopped
11:21:27 gapi.go:209: lang: Generating new graph...
11:21:27 autoedge.go:92: Compile: Adding AutoEdges...
11:21:27 lang.go:168: lang: funcs: func `str(nginx)` changed
11:21:27 lang.go:168: lang: funcs: func `str(nginx)` stopped
11:21:27 lang.go:168: lang: funcs: func `str(mariadb)` changed
11:21:27 lang.go:168: lang: funcs: func `str(mariadb)` stopped
11:21:27 lang.go:168: lang: funcs: func `str(running)` started
11:21:27 lang.go:168: lang: funcs: func `str(running)` changed
11:21:27 lang.go:168: lang: funcs: func `str(running)` started
11:21:27 lang.go:168: lang: funcs: func `str(running)` changed
11:21:27 autogroup.go:352: Compile: Grouping: Algorithm: NonReachabilityGrouper...
11:21:27 mgraph.go:99: State: 0 -> 1
11:21:27 mgraph.go:162: svc[mariadb]: Started
11:21:27 mgraph.go:162: svc[php-fpm]: Started
11:21:27 svc.go:167: Watching: mariadb.service
11:21:27 mgraph.go:162: svc[nginx]: Started
11:21:27 svc.go:271: svc[mariadb]: Apply
11:21:27 svc.go:171: Svc event: map[mariadb.service:0xc4203bcca8]
11:21:27 svc.go:180: Svc[mariadb.service]->Stopped
11:21:27 svc.go:167: Watching: php-fpm.service
11:21:27 mgraph.go:182: State: 1 -> 2
11:21:27 main.go:623: Main: Graph: Vertices(3), Edges(0)
11:21:27 main.go:399: Main: Waiting...
11:21:27 gapi.go:209: lang: Generating new graph...
11:21:27 lang.go:168: lang: funcs: func `str(running)` stopped
11:21:27 mgraph.go:188: State: 2 -> 3
11:21:27 svc.go:167: Watching: mariadb.service
11:21:27 svc.go:167: Watching: nginx.service
11:21:27 svc.go:171: Svc event: map[php-fpm.service:0xc420dee2a0]
11:21:27 svc.go:178: Svc[php-fpm.service]->Started
11:21:27 svc.go:167: Watching: php-fpm.service
11:21:29 mgraph.go:198: State: 3 -> 4
11:21:29 lang.go:249: lang: Running interpret...
11:21:29 main.go:552: Main: GraphSync...
11:21:29 autoedge.go:92: Compile: Adding AutoEdges...
11:21:29 autogroup.go:352: Compile: Grouping: Algorithm: NonReachabilityGrouper...
11:21:29 mgraph.go:99: State: 4 -> 1
11:21:29 mgraph.go:182: State: 1 -> 2
11:21:29 main.go:623: Main: Graph: Vertices(3), Edges(0)
11:21:29 main.go:399: Main: Waiting...
11:21:29 gapi.go:209: lang: Generating new graph...
11:21:29 lang.go:168: lang: funcs: func `str(running)` stopped
11:21:29 mgraph.go:188: State: 2 -> 3
11:21:29 svc.go:167: Watching: mariadb.service
11:21:29 svc.go:167: Watching: nginx.service
11:21:29 svc.go:171: Svc event: map[mariadb.service:0xc420df8ca8]
11:21:29 svc.go:186: Svc[mariadb.service]->Activating
11:21:29 svc.go:167: Watching: php-fpm.service
11:21:29 svc.go:171: Svc event: map[nginx.service:0xc42084b4f8]
11:21:29 svc.go:178: Svc[nginx.service]->Started
11:21:29 svc.go:167: Watching: mariadb.service
11:21:29 svc.go:167: Watching: nginx.service
11:21:29 mgraph.go:198: State: 3 -> 4
11:21:29 lang.go:249: lang: Running interpret...
11:21:29 main.go:552: Main: GraphSync...
11:21:29 autoedge.go:92: Compile: Adding AutoEdges...
11:21:29 autogroup.go:352: Compile: Grouping: Algorithm: NonReachabilityGrouper...
11:21:29 mgraph.go:99: State: 4 -> 1
11:21:29 mgraph.go:182: State: 1 -> 2
11:21:29 main.go:623: Main: Graph: Vertices(3), Edges(0)
11:21:29 main.go:399: Main: Waiting...
11:21:29 mgraph.go:188: State: 2 -> 3
11:21:29 gapi.go:209: lang: Generating new graph...
11:21:29 svc.go:167: Watching: php-fpm.service
11:21:29 svc.go:167: Watching: nginx.service
11:21:29 svc.go:167: Watching: mariadb.service
11:21:29 svc.go:171: Svc event: map[mariadb.service:0xc420de8ca8]
11:21:29 svc.go:178: Svc[mariadb.service]->Started
11:21:29 svc.go:167: Watching: mariadb.service
11:21:29 mgraph.go:198: State: 3 -> 4
11:21:29 lang.go:249: lang: Running interpret...
11:21:29 main.go:552: Main: GraphSync...
11:21:29 autoedge.go:92: Compile: Adding AutoEdges...
11:21:29 autogroup.go:352: Compile: Grouping: Algorithm: NonReachabilityGrouper...
11:21:29 mgraph.go:99: State: 4 -> 1
11:21:29 mgraph.go:182: State: 1 -> 2
11:21:29 main.go:623: Main: Graph: Vertices(3), Edges(0)
11:21:29 main.go:399: Main: Waiting...
11:21:29 gapi.go:209: lang: Generating new graph...
11:21:29 mgraph.go:188: State: 2 -> 3
11:21:29 svc.go:167: Watching: nginx.service
11:21:29 svc.go:167: Watching: php-fpm.service
11:21:29 svc.go:167: Watching: mariadb.service
11:21:29 mgraph.go:198: State: 3 -> 4
11:21:29 lang.go:249: lang: Running interpret...
11:21:29 main.go:552: Main: GraphSync...
11:21:29 autoedge.go:92: Compile: Adding AutoEdges...
11:21:29 autogroup.go:352: Compile: Grouping: Algorithm: NonReachabilityGrouper...
11:21:29 mgraph.go:99: State: 4 -> 1
11:21:29 mgraph.go:182: State: 1 -> 2
11:21:29 main.go:623: Main: Graph: Vertices(3), Edges(0)
11:21:29 main.go:399: Main: Waiting...
11:21:29 mgraph.go:188: State: 2 -> 3
11:21:29 svc.go:167: Watching: mariadb.service
11:21:29 svc.go:167: Watching: php-fpm.service
11:21:29 svc.go:167: Watching: nginx.service
11:21:29 mgraph.go:198: State: 3 -> 4
11:21:29 lang.go:249: lang: Running interpret...
11:21:29 main.go:552: Main: GraphSync...
11:21:29 autoedge.go:92: Compile: Adding AutoEdges...
11:21:29 autogroup.go:352: Compile: Grouping: Algorithm: NonReachabilityGrouper...
11:21:29 mgraph.go:99: State: 4 -> 1
11:21:29 mgraph.go:182: State: 1 -> 2
11:21:29 main.go:623: Main: Graph: Vertices(3), Edges(0)
11:21:29 main.go:399: Main: Waiting...
11:21:29 svc.go:167: Watching: mariadb.service
11:21:29 svc.go:167: Watching: php-fpm.service
11:21:29 svc.go:167: Watching: nginx.service
11:21:36 svc.go:171: Svc event: map[mariadb.service:0xc42084aca8]
11:21:36 svc.go:188: Svc[mariadb.service]->Deactivating
11:21:36 svc.go:167: Watching: mariadb.service
11:21:36 svc.go:271: svc[mariadb]: Apply
11:21:36 actions.go:419: svc[mariadb]: CheckApply errored: could not Process() successfully: failed to start unit: Transaction is destructive.
11:21:36 mgraph.go:164: svc[mariadb]: Exited with failure: could not Process() successfully: failed to start unit: Transaction is destructive.

[xet7]

Well, at least Ctrl-c did work this time:

^C11:25:36 cli.go:146: Interrupted by ^C
11:25:36 main.go:724: Main: Destroy...
11:25:36 mgraph.go:188: State: 2 -> 3
11:25:36 mgraph.go:198: State: 3 -> 4
11:25:36 mgraph.go:167: svc[nginx]: Exited
11:25:36 mgraph.go:167: svc[php-fpm]: Exited
11:25:36 etcd.go:465: Etcd: Destroy: Unvolunteering...
11:25:36 etcd.go:1248: Etcd: Members: List: [subdomain.example.com]
11:25:36 etcd.go:1271: Etcd: Leader: subdomain.example.com
11:25:36 etcd.go:1290: Etcd: Volunteers: []
11:25:36 etcd.go:1294: Etcd: Quitters: [subdomain.example.com]
11:25:36 etcd.go:1298: Etcd: Quitters: Shutting down self...
11:25:36 etcd.go:1806: Etcd: ApplyDeltaEvents: Event(DELETE): subdomain.example.com
11:25:36 etcd.go:1450: Etcd: Nominated: []
11:25:36 etcd.go:1532: Etcd: DestroyServer...
11:25:36 etcd.go:1773: Etcd: DestroyServer: Destroying...
WARNING: 2018/03/12 11:25:36 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: Error while dialing dial tcp 127.0.0.1:2379: getsockopt: connection refused"; Reconnecting to {127.0.0.1:2379 0  <nil>}
11:25:36 etcd.go:1777: Etcd: DestroyServer: Done closing...
11:25:36 etcd.go:1784: Etcd: DestroyServer: Unlocking server...
11:25:36 etcd.go:1806: Etcd: ApplyDeltaEvents: Event(DELETE): subdomain.example.com
11:25:36 etcd.go:1622: Etcd: Endpoints: []
11:25:36 etcd.go:672: Etcd: CtxError: Reason: CtxReconnectErr: endpoint list changed
11:25:36 etcd.go:698: Etcd: CtxError: Cancelling 4 operations...
11:25:36 etcd.go:705: Etcd: CtxError: Reconnecting...
11:25:36 etcd.go:476: Etcd: Destroy: Cancelling 1 operations...
11:25:36 etcd.go:951: Etcd: Exiting loop shortly...
11:25:36 etcd.go:335: Etcd: Connect: Endpoints: []
WARNING: 2018/03/12 11:25:36 grpc: addrConn.transportMonitor exits due to: context canceled
11:25:36 etcd.go:349: Etcd: Connect: CtxError...
11:25:36 etcd.go:351: Etcd: Connect: CtxError: Fatal: exit in progress
11:25:36 etcd.go:789: Etcd: Exiting loop shortly...
11:25:39 etcd.go:798: Etcd: Exiting callback loop!
11:25:39 etcd.go:960: Etcd: Exiting loop!
11:25:39 main.go:752: Goodbye!

[xet7]

With above destructive behaviour (yes, I did type sudo systemctl stop mariadb), mgmt does not start mariadb again.

[purpleidea]

@xet7

Transaction is destructive

What a weird thing! Well there seems to obviously be some sort of reason systemd is telling us this when it tries to start the service.

What is happening is that mgmt notices the service is stopped, then it tries to start it, and the start command fails with "Transaction is destructive". Understanding why and when systemd would tell the user that is at the root of understanding this issue.

If you're in a debugging mood, care to ask around in #systemd on Freenode to see if they can explain the error message?

[purpleidea]

@xet7

mgmt does not start mariadb again.

Once a resource exits with a permanent error, it will stop watching that service. It's a feature since in situations of permanent errors, it usually means something is permanently wrong. (In this case perhaps a case we don't handle properly, or something else we should be detecting depending on the reason.)

[xet7]

@purpleidea

Yes I'll ask about this at #systemd