Enless loop of watching

[aequitas]

Versions:

• mgmt version (eg: mgmt --version): 0.0.14-13-g7e6d013-dirty

• operating system/distribution (eg: uname -a): Linux faalserver 3.16.0-4-amd64 #1 SMP Debian 3.16.51-2 (2017-12-03) x86_64 GNU/Linux

• golang version (eg: go version): ?

Description:

When converting Puppet code to YAML using @ffrank module some configurations can cause a lot of Watching: <service name>.service messages to be displayed. Mgmt never converges (not tested until eternity though).

Command used are in log output below.

Puppet source:

class base {
  notice("fqdn=${::fqdn}, env=${::env}")

  package { 'resolvconf': ensure => latest}
  ~> service { 'resolvconf': ensure => running, enable => true}
  package { 'dnsmasq': ensure => latest}
  ~> service { 'dnsmasq': ensure => running, enable => true}
}

Generate YAML:

---
graph: faalserver.faalkaart.test
comment: generated from puppet catalog for faalserver.faalkaart.test
resources:
  exec:
  - name: Package:resolvconf
    cmd: |-
      puppet yamlresource package 'resolvconf' '{"provider": "apt", "ensure": "latest", "configfiles": "keep", "reinstall_on_refresh": "false",
        "loglevel": "notice"}'
    timeout: 30
    shell: "/bin/bash"
    watchshell: "/bin/bash"
    ifshell: "/bin/bash"
    watchcmd: 'while : ; do echo "puppet run interval passed" ; /bin/sleep 1800 ;
      done'
    ifcmd: |-
      puppet yamlresource package 'resolvconf' '{"provider": "apt", "ensure": "latest", "configfiles": "keep", "reinstall_on_refresh": "false",
        "loglevel": "notice"}' --noop --color=false | grep -q ^Notice:
    state: present
    pollint: 0
  - name: Package:dnsmasq
    cmd: |-
      puppet yamlresource package 'dnsmasq' '{"provider": "apt", "ensure": "latest", "configfiles": "keep", "reinstall_on_refresh": "false",
        "loglevel": "notice"}'
    timeout: 30
    shell: "/bin/bash"
    watchshell: "/bin/bash"
    ifshell: "/bin/bash"
    watchcmd: 'while : ; do echo "puppet run interval passed" ; /bin/sleep 1800 ;
      done'
    ifcmd: |-
      puppet yamlresource package 'dnsmasq' '{"provider": "apt", "ensure": "latest", "configfiles": "keep", "reinstall_on_refresh": "false",
        "loglevel": "notice"}' --noop --color=false | grep -q ^Notice:
    state: present
    pollint: 0
  svc:
  - name: resolvconf
    state: running
    startup: enabled
  - name: dnsmasq
    state: running
    startup: enabled
  noop:
  - name: admissible_Stage[main]
  - name: completed_Stage[main]
  - name: admissible_Class[Settings]
  - name: completed_Class[Settings]
  - name: admissible_Class[Main]
  - name: completed_Class[Main]
  - name: admissible_Class[Base]
  - name: completed_Class[Base]
edges:
- name: Whit[Admissible_class[Base]] -> Package[resolvconf]
  from:
    kind: noop
    name: admissible_Class[Base]
  to:
    kind: exec
    name: Package:resolvconf
- name: Package[resolvconf] -> Service[resolvconf]
  from:
    kind: exec
    name: Package:resolvconf
  to:
    kind: svc
    name: resolvconf
- name: Whit[Admissible_class[Base]] -> Service[resolvconf]
  from:
    kind: noop
    name: admissible_Class[Base]
  to:
    kind: svc
    name: resolvconf
- name: Whit[Admissible_class[Base]] -> Package[dnsmasq]
  from:
    kind: noop
    name: admissible_Class[Base]
  to:
    kind: exec
    name: Package:dnsmasq
- name: Package[dnsmasq] -> Service[dnsmasq]
  from:
    kind: exec
    name: Package:dnsmasq
  to:
    kind: svc
    name: dnsmasq
- name: Whit[Admissible_class[Base]] -> Service[dnsmasq]
  from:
    kind: noop
    name: admissible_Class[Base]
  to:
    kind: svc
    name: dnsmasq
- name: Whit[Completed_class[Settings]] -> Whit[Completed_stage[main]]
  from:
    kind: noop
    name: completed_Class[Settings]
  to:
    kind: noop
    name: completed_Stage[main]
- name: Whit[Completed_class[Main]] -> Whit[Completed_stage[main]]
  from:
    kind: noop
    name: completed_Class[Main]
  to:
    kind: noop
    name: completed_Stage[main]
- name: Whit[Completed_class[Base]] -> Whit[Completed_stage[main]]
  from:
    kind: noop
    name: completed_Class[Base]
  to:
    kind: noop
    name: completed_Stage[main]
- name: Whit[Admissible_stage[main]] -> Whit[Admissible_class[Settings]]
  from:
    kind: noop
    name: admissible_Stage[main]
  to:
    kind: noop
    name: admissible_Class[Settings]
- name: Whit[Admissible_class[Settings]] -> Whit[Completed_class[Settings]]
  from:
    kind: noop
    name: admissible_Class[Settings]
  to:
    kind: noop
    name: completed_Class[Settings]
- name: Whit[Admissible_stage[main]] -> Whit[Admissible_class[Main]]
  from:
    kind: noop
    name: admissible_Stage[main]
  to:
    kind: noop
    name: admissible_Class[Main]
- name: Whit[Admissible_class[Main]] -> Whit[Completed_class[Main]]
  from:
    kind: noop
    name: admissible_Class[Main]
  to:
    kind: noop
    name: completed_Class[Main]
- name: Whit[Admissible_stage[main]] -> Whit[Admissible_class[Base]]
  from:
    kind: noop
    name: admissible_Stage[main]
  to:
    kind: noop
    name: admissible_Class[Base]
- name: Package[resolvconf] -> Whit[Completed_class[Base]]
  from:
    kind: exec
    name: Package:resolvconf
  to:
    kind: noop
    name: completed_Class[Base]
- name: Service[resolvconf] -> Whit[Completed_class[Base]]
  from:
    kind: svc
    name: resolvconf
  to:
    kind: noop
    name: completed_Class[Base]
- name: Package[dnsmasq] -> Whit[Completed_class[Base]]
  from:
    kind: exec
    name: Package:dnsmasq
  to:
    kind: noop
    name: completed_Class[Base]
- name: Service[dnsmasq] -> Whit[Completed_class[Base]]
  from:
    kind: svc
    name: dnsmasq
  to:
    kind: noop
    name: completed_Class[Base]

Log output:

puppet mgmtgraph print --code "include base" --modulepath=modules:vendor/modules --hiera_config=hiera.yaml --conservative > puppet.yaml
Error: Package[resolvconf] uses ensure => latest which currently cannot be translated for mgmt (defaulting to 'installed')
Warning: emitting a `exec puppet resource` node for Package[resolvconf] because of the errors above
Error: Package[dnsmasq] uses ensure => latest which currently cannot be translated for mgmt (defaulting to 'installed')
Warning: emitting a `exec puppet resource` node for Package[dnsmasq] because of the errors above
mgmt run --tmp-prefix --converged-timeout=1 --yaml=puppet.yaml
22:43:16 hello.go:46: This is: mgmt, version: 0.0.14-12-g94c8bc1-dirty
22:43:16 hello.go:47: Main: Start: 1518302596727969984
22:43:16 main.go:230: Main: Warning: Working prefix directory is temporary!
22:43:16 main.go:236: Main: Working prefix is: /tmp/mgmt-faalserver-299048825
22:43:17 pgp.go:88: PGP: Created key: 385390D6
22:43:17 main.go:329: Main: Seeds: No seeds specified!
22:43:17 etcd.go:409: Etcd: Bootstrapping...
22:43:17 etcd.go:1437: Etcd: Nominated: faalserver=http://127.0.0.1:2380
22:43:17 etcd.go:1452: Etcd: StartServer(newCluster: true): faalserver=http://127.0.0.1:2380
22:43:17 etcd.go:1722: Etcd: StartServer: Starting server...
22:43:17 etcd.go:324: Etcd: Connect: Endpoints: []
22:43:17 etcd.go:338: Etcd: Connect: CtxError...
22:43:17 etcd.go:618: Etcd: CtxError: Reason: CtxDelayErr(1s): No endpoints available yet!
22:43:18 etcd.go:1729: Etcd: StartServer: Done starting server!
22:43:18 etcd.go:1747: Etcd: StartServer: Server running...
22:43:18 etcd.go:1475: Etcd: Addresses are: http://127.0.0.1:2379
22:43:18 etcd.go:322: Etcd: Connect: Endpoints: faalserver=http://127.0.0.1:2379
22:43:18 etcd.go:1794: Etcd: ApplyDeltaEvents: Event(PUT): faalserver
22:43:18 etcd.go:1437: Etcd: Nominated: faalserver=http://127.0.0.1:2380
22:43:18 etcd.go:429: Etcd: Startup: Volunteering...
22:43:18 etcd.go:1643: Etcd: Ideal cluster size is now: 5
22:43:18 etcd.go:996: Etcd: Set(/_mgmt/idealClusterSize): &{cluster_id:2037210783374497686 member_id:13195394291058371180 revision:4 raft_term:2  <nil>}
22:43:18 etcd.go:1237: Etcd: Members: List: [faalserver]
22:43:18 etcd.go:1260: Etcd: Leader: faalserver
22:43:18 etcd.go:1279: Etcd: Volunteers: [faalserver]
22:43:18 etcd.go:1283: Etcd: Quitters: []
22:43:18 etcd.go:1295: Etcd: Candidates: []
22:43:18 etcd.go:1237: Etcd: Members: List: [faalserver]
22:43:18 etcd.go:1260: Etcd: Leader: faalserver
22:43:18 etcd.go:1279: Etcd: Volunteers: [faalserver]
22:43:18 etcd.go:1283: Etcd: Quitters: []
22:43:18 etcd.go:1295: Etcd: Candidates: []
22:43:19 main.go:718: Main: Remotes: Run: Ready!
22:43:19 main.go:428: Main: Waiting...
22:43:19 main.go:428: Main: Waiting...
22:43:19 gapi.go:175: yaml: Generating new graph...
22:43:19 main.go:805: Main: Running...
22:43:19 main.go:581: Main: GraphSync...
22:43:19 autoedge.go:92: Compile: Adding AutoEdges...
22:43:19 autoedge.go:109: noop[admissible_Class[Base]]: No auto edges were found!
22:43:19 autoedge.go:109: noop[admissible_Class[Main]]: No auto edges were found!
22:43:19 autoedge.go:109: noop[admissible_Class[Settings]]: No auto edges were found!
22:43:19 autoedge.go:109: noop[admissible_Stage[main]]: No auto edges were found!
22:43:19 autoedge.go:109: noop[completed_Class[Base]]: No auto edges were found!
22:43:19 autoedge.go:109: noop[completed_Class[Main]]: No auto edges were found!
22:43:19 autoedge.go:109: noop[completed_Class[Settings]]: No auto edges were found!
22:43:19 autoedge.go:109: noop[completed_Stage[main]]: No auto edges were found!
22:43:19 autogroup.go:352: Compile: Grouping: Algorithm: NonReachabilityGrouper...
22:43:19 autogroup.go:352: Compile: Grouping: Success for: noop[admissible_Class[Main]] into noop[admissible_Class[Base]]
22:43:19 autogroup.go:352: Compile: Grouping: Success for: noop[admissible_Class[Settings]] into noop[admissible_Class[Base]]
22:43:19 autogroup.go:352: Compile: Grouping: Success for: noop[completed_Class[Main]] into noop[completed_Class[Base]]
22:43:19 autogroup.go:352: Compile: Grouping: Success for: noop[completed_Class[Settings]] into noop[completed_Class[Base]]
22:43:19 mgraph.go:99: State: 0 -> 1
22:43:19 mgraph.go:162: noop[completed_Stage[main]]: Started
22:43:19 mgraph.go:162: noop[completed_Class[Base]]: Started
22:43:19 mgraph.go:162: svc[dnsmasq]: Started
22:43:19 mgraph.go:162: exec[Package:dnsmasq]: Started
22:43:19 svc.go:167: Watching: dnsmasq.service
22:43:19 svc.go:171: Svc event: map[dnsmasq.service:0xc4203720c8]
22:43:19 svc.go:178: Svc[dnsmasq.service]->Started
22:43:19 mgraph.go:162: svc[resolvconf]: Started
22:43:19 exec.go:172: exec[Package:dnsmasq]: Watch output: puppet run interval passed
22:43:19 svc.go:167: Watching: dnsmasq.service
22:43:19 mgraph.go:162: exec[Package:resolvconf]: Started
22:43:19 svc.go:167: Watching: resolvconf.service
22:43:19 mgraph.go:162: noop[admissible_Class[Base]]: Started
22:43:19 mgraph.go:162: noop[admissible_Stage[main]]: Started
22:43:19 mgraph.go:182: State: 1 -> 2
22:43:19 main.go:652: Main: Graph: Vertices(8), Edges(12)
22:43:19 main.go:428: Main: Waiting...
22:43:19 exec.go:172: exec[Package:resolvconf]: Watch output: puppet run interval passed
22:43:19 svc.go:167: Watching: dnsmasq.service
22:43:19 svc.go:167: Watching: resolvconf.service
22:43:19 svc.go:171: Svc event: map[resolvconf.service:0xc4203ec8f8]
22:43:19 svc.go:178: Svc[resolvconf.service]->Started
22:43:19 svc.go:167: Watching: dnsmasq.service
22:43:19 svc.go:167: Watching: resolvconf.service
22:43:19 svc.go:167: Watching: resolvconf.service
22:43:21 exec.go:240: Error: command failed to run: puppet yamlresource package 'resolvconf' '{"provider": "apt", "ensure": "latest", "configfiles": "keep", "reinstall_on_refresh": "false",
  "loglevel": "notice"}' --noop --color=false | grep -q ^Notice:
22:43:21 svc.go:167: Watching: resolvconf.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: resolvconf.service
22:43:21 svc.go:167: Watching: resolvconf.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: resolvconf.service
22:43:21 svc.go:167: Watching: resolvconf.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: resolvconf.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: resolvconf.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: resolvconf.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: resolvconf.service
22:43:21 svc.go:167: Watching: resolvconf.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 exec.go:240: Error: command failed to run: puppet yamlresource package 'dnsmasq' '{"provider": "apt", "ensure": "latest", "configfiles": "keep", "reinstall_on_refresh": "false",
  "loglevel": "notice"}' --noop --color=false | grep -q ^Notice:
22:43:21 svc.go:167: Watching: resolvconf.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: dnsmasq.service
22:43:21 svc.go:167: Watching: dnsmasq.service

### SNIP###

22:43:25 svc.go:167: Watching: dnsmasq.service
22:43:25 svc.go:167: Watching: dnsmasq.service
22:43:25 svc.go:167: Watching: dnsmasq.service
22:43:25 svc.go:167: Watching: resolvconf.service
22:43:25 svc.go:167: Watching: resolvconf.service
22:43:25 svc.go:167: Watching: dnsmasq.service
22:43:25 svc.go:167: Watching: dnsmasq.service
^C22:43:25 cli.go:154: Interrupted by ^C
22:43:25 main.go:809: Main: Destroy...
22:43:25 mgraph.go:188: State: 2 -> 3
22:43:25 svc.go:167: Watching: dnsmasq.service
22:43:25 svc.go:167: Watching: dnsmasq.service
22:43:25 svc.go:167: Watching: dnsmasq.service
22:43:25 svc.go:167: Watching: dnsmasq.service
22:43:25 svc.go:167: Watching: dnsmasq.service
22:43:25 svc.go:167: Watching: dnsmasq.service
22:43:25 mgraph.go:198: State: 3 -> 4
22:43:25 mgraph.go:167: noop[admissible_Stage[main]]: Exited
22:43:25 mgraph.go:167: noop[admissible_Class[Base]]: Exited
22:43:25 mgraph.go:167: exec[Package:dnsmasq]: Exited
22:43:25 mgraph.go:167: svc[dnsmasq]: Exited
22:43:25 mgraph.go:167: exec[Package:resolvconf]: Exited
22:43:25 mgraph.go:167: svc[resolvconf]: Exited
22:43:25 mgraph.go:167: noop[completed_Class[Base]]: Exited
22:43:25 mgraph.go:167: noop[completed_Stage[main]]: Exited
22:43:25 etcd.go:454: Etcd: Destroy: Unvolunteering...
22:43:25 etcd.go:1237: Etcd: Members: List: [faalserver]
22:43:25 etcd.go:1260: Etcd: Leader: faalserver
22:43:25 etcd.go:1279: Etcd: Volunteers: []
22:43:25 etcd.go:1283: Etcd: Quitters: [faalserver]
22:43:25 etcd.go:1287: Etcd: Quitters: Shutting down self...
22:43:25 etcd.go:1794: Etcd: ApplyDeltaEvents: Event(DELETE): faalserver
22:43:25 etcd.go:1439: Etcd: Nominated: []
22:43:25 etcd.go:1521: Etcd: DestroyServer...
22:43:25 etcd.go:1761: Etcd: DestroyServer: Destroying...
22:43:26 main.go:376: Main: Converged for 1 seconds, exiting!
22:43:32 etcd.go:1765: Etcd: DestroyServer: Done closing...
22:43:32 etcd.go:1772: Etcd: DestroyServer: Unlocking server...
22:43:32 etcd.go:1794: Etcd: ApplyDeltaEvents: Event(DELETE): faalserver
22:43:32 etcd.go:1611: Etcd: Endpoints: []
22:43:32 etcd.go:661: Etcd: CtxError: Reason: CtxReconnectErr: endpoint list changed
22:43:32 etcd.go:687: Etcd: CtxError: Cancelling 6 operations...
22:43:32 etcd.go:694: Etcd: CtxError: Reconnecting...
22:43:32 etcd.go:465: Etcd: Destroy: Cancelling 0 operations...
22:43:32 etcd.go:940: Etcd: Exiting loop shortly...
22:43:32 etcd.go:324: Etcd: Connect: Endpoints: []
22:43:32 etcd.go:338: Etcd: Connect: CtxError...
22:43:32 etcd.go:340: Etcd: Connect: CtxError: Fatal: exit in progress
22:43:32 etcd.go:778: Etcd: Exiting loop shortly...
22:43:35 etcd.go:949: Etcd: Exiting loop!
22:43:35 etcd.go:787: Etcd: Exiting callback loop!
22:43:35 main.go:843: Goodbye!

[aequitas]

digraph faalserver.faalkaart.test {
    label="faalserver.faalkaart.test";
    "svc[dnsmasq]" [label="svc[dnsmasq]"];
    "noop[completed_Class[Base]]" [label="noop[completed_Class[Base]]"];
    "svc[resolvconf]" [label="svc[resolvconf]"];
    "exec[Package:resolvconf]" [label="exec[Package:resolvconf]"];
    "noop[admissible_Class[Base]]" [label="noop[admissible_Class[Base]]"];
    "noop[completed_Stage[main]]" [label="noop[completed_Stage[main]]"];
    "exec[Package:dnsmasq]" [label="exec[Package:dnsmasq]"];
    "noop[admissible_Stage[main]]" [label="noop[admissible_Stage[main]]"];
    "svc[dnsmasq]" -> "noop[completed_Class[Base]]" [label="Service[dnsmasq] -> Whit[Completed_class[Base]]"];
    "noop[completed_Class[Base]]" -> "noop[completed_Stage[main]]" [label="Whit[Completed_class[Base]] -> Whit[Completed_stage[main]]"];
    "svc[resolvconf]" -> "noop[completed_Class[Base]]" [label="Service[resolvconf] -> Whit[Completed_class[Base]]"];
    "exec[Package:resolvconf]" -> "noop[completed_Class[Base]]" [label="Package[resolvconf] -> Whit[Completed_class[Base]]"];
    "exec[Package:resolvconf]" -> "svc[resolvconf]" [label="Package[resolvconf] -> Service[resolvconf]"];
    "noop[admissible_Class[Base]]" -> "svc[dnsmasq]" [label="Whit[Admissible_class[Base]] -> Service[dnsmasq]"];
    "noop[admissible_Class[Base]]" -> "exec[Package:resolvconf]" [label="Whit[Admissible_class[Base]] -> Package[resolvconf]"];
    "noop[admissible_Class[Base]]" -> "svc[resolvconf]" [label="Whit[Admissible_class[Base]] -> Service[resolvconf]"];
    "noop[admissible_Class[Base]]" -> "exec[Package:dnsmasq]" [label="Whit[Admissible_class[Base]] -> Package[dnsmasq]"];
    "exec[Package:dnsmasq]" -> "svc[dnsmasq]" [label="Package[dnsmasq] -> Service[dnsmasq]"];
    "exec[Package:dnsmasq]" -> "noop[completed_Class[Base]]" [label="Package[dnsmasq] -> Whit[Completed_class[Base]]"];
    "noop[admissible_Stage[main]]" -> "noop[admissible_Class[Base]]" [label="Whit[Admissible_stage[main]] -> Whit[Admissible_class[Base]]"];
}

[aequitas]

[aequitas]

--sema=1 might mitigate a little, still a lot of Watching: messages but at least it converges.

Unabridged:

# mgmt run --tmp-prefix --converged-timeout=1 --sema=1  --yaml=puppet.yaml
23:13:23 hello.go:46: This is: mgmt, version: 0.0.14-13-g7e6d013-dirty
23:13:23 hello.go:47: Main: Start: 1518304403541787631
23:13:23 main.go:230: Main: Warning: Working prefix directory is temporary!
23:13:23 main.go:236: Main: Working prefix is: /tmp/mgmt-faalserver-586901869
23:13:24 pgp.go:88: PGP: Created key: 1A55205E
23:13:24 main.go:329: Main: Seeds: No seeds specified!
23:13:24 etcd.go:324: Etcd: Connect: Endpoints: []
23:13:24 etcd.go:338: Etcd: Connect: CtxError...
23:13:24 etcd.go:618: Etcd: CtxError: Reason: CtxDelayErr(1s): No endpoints available yet!
23:13:24 etcd.go:409: Etcd: Bootstrapping...
23:13:24 etcd.go:1437: Etcd: Nominated: faalserver=http://127.0.0.1:2380
23:13:24 etcd.go:1452: Etcd: StartServer(newCluster: true): faalserver=http://127.0.0.1:2380
23:13:24 etcd.go:1722: Etcd: StartServer: Starting server...
23:13:24 etcd.go:1729: Etcd: StartServer: Done starting server!
23:13:24 etcd.go:1747: Etcd: StartServer: Server running...
23:13:24 etcd.go:1475: Etcd: Addresses are: http://127.0.0.1:2379
23:13:25 etcd.go:322: Etcd: Connect: Endpoints: faalserver=http://127.0.0.1:2379
23:13:25 etcd.go:1794: Etcd: ApplyDeltaEvents: Event(PUT): faalserver
23:13:25 etcd.go:1437: Etcd: Nominated: faalserver=http://127.0.0.1:2380
23:13:25 etcd.go:429: Etcd: Startup: Volunteering...
23:13:25 etcd.go:1643: Etcd: Ideal cluster size is now: 5
23:13:25 etcd.go:996: Etcd: Set(/_mgmt/idealClusterSize): &{cluster_id:2037210783374497686 member_id:13195394291058371180 revision:4 raft_term:2  <nil>}
23:13:25 etcd.go:1237: Etcd: Members: List: [faalserver]
23:13:25 etcd.go:1260: Etcd: Leader: faalserver
23:13:25 etcd.go:1279: Etcd: Volunteers: [faalserver]
23:13:25 etcd.go:1283: Etcd: Quitters: []
23:13:25 etcd.go:1295: Etcd: Candidates: []
23:13:25 etcd.go:1237: Etcd: Members: List: [faalserver]
23:13:25 etcd.go:1260: Etcd: Leader: faalserver
23:13:25 etcd.go:1279: Etcd: Volunteers: [faalserver]
23:13:25 etcd.go:1283: Etcd: Quitters: []
23:13:25 etcd.go:1295: Etcd: Candidates: []
23:13:26 main.go:428: Main: Waiting...
23:13:26 main.go:718: Main: Remotes: Run: Ready!
23:13:26 main.go:805: Main: Running...
23:13:26 main.go:428: Main: Waiting...
23:13:26 gapi.go:175: yaml: Generating new graph...
23:13:26 main.go:581: Main: GraphSync...
23:13:26 autoedge.go:92: Compile: Adding AutoEdges...
23:13:26 autoedge.go:109: noop[admissible_Class[Base]]: No auto edges were found!
23:13:26 autoedge.go:109: noop[admissible_Class[Main]]: No auto edges were found!
23:13:26 autoedge.go:109: noop[admissible_Class[Settings]]: No auto edges were found!
23:13:26 autoedge.go:109: noop[admissible_Stage[main]]: No auto edges were found!
23:13:26 autoedge.go:109: noop[completed_Class[Base]]: No auto edges were found!
23:13:26 autoedge.go:109: noop[completed_Class[Main]]: No auto edges were found!
23:13:26 autoedge.go:109: noop[completed_Class[Settings]]: No auto edges were found!
23:13:26 autoedge.go:109: noop[completed_Stage[main]]: No auto edges were found!
23:13:26 autogroup.go:352: Compile: Grouping: Algorithm: NonReachabilityGrouper...
23:13:26 autogroup.go:352: Compile: Grouping: Success for: noop[admissible_Class[Main]] into noop[admissible_Class[Base]]
23:13:26 autogroup.go:352: Compile: Grouping: Success for: noop[admissible_Class[Settings]] into noop[admissible_Class[Base]]
23:13:26 autogroup.go:352: Compile: Grouping: Success for: noop[completed_Class[Main]] into noop[completed_Class[Base]]
23:13:26 autogroup.go:352: Compile: Grouping: Success for: noop[completed_Class[Settings]] into noop[completed_Class[Base]]
23:13:26 mgraph.go:99: State: 0 -> 1
23:13:26 mgraph.go:162: noop[completed_Stage[main]]: Started
23:13:26 mgraph.go:162: noop[completed_Class[Base]]: Started
23:13:26 mgraph.go:162: svc[resolvconf]: Started
23:13:26 mgraph.go:162: exec[Package:resolvconf]: Started
23:13:26 svc.go:167: Watching: resolvconf.service
23:13:26 mgraph.go:162: svc[dnsmasq]: Started
23:13:26 exec.go:172: exec[Package:resolvconf]: Watch output: puppet run interval passed
23:13:26 mgraph.go:162: exec[Package:dnsmasq]: Started
23:13:26 svc.go:167: Watching: dnsmasq.service
23:13:26 mgraph.go:162: noop[admissible_Class[Base]]: Started
23:13:26 mgraph.go:162: noop[admissible_Stage[main]]: Started
23:13:26 mgraph.go:182: State: 1 -> 2
23:13:26 main.go:652: Main: Graph: Vertices(8), Edges(12)
23:13:26 main.go:428: Main: Waiting...
23:13:26 svc.go:167: Watching: resolvconf.service
23:13:26 svc.go:167: Watching: dnsmasq.service
23:13:26 exec.go:172: exec[Package:dnsmasq]: Watch output: puppet run interval passed
23:13:26 svc.go:171: Svc event: map[dnsmasq.service:0xc4203420c8]
23:13:26 svc.go:178: Svc[dnsmasq.service]->Started
23:13:26 svc.go:167: Watching: dnsmasq.service
23:13:27 svc.go:171: Svc event: map[resolvconf.service:0xc4205228f8]
23:13:27 svc.go:178: Svc[resolvconf.service]->Started
23:13:27 svc.go:167: Watching: resolvconf.service
23:13:28 svc.go:167: Watching: dnsmasq.service
23:13:28 svc.go:167: Watching: resolvconf.service
23:13:28 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: dnsmasq.service
23:13:30 svc.go:167: Watching: resolvconf.service
23:13:31 main.go:376: Main: Converged for 1 seconds, exiting!
23:13:31 main.go:809: Main: Destroy...
23:13:31 mgraph.go:188: State: 2 -> 3
23:13:31 mgraph.go:198: State: 3 -> 4
23:13:31 mgraph.go:167: noop[admissible_Stage[main]]: Exited
23:13:31 mgraph.go:167: noop[admissible_Class[Base]]: Exited
23:13:31 mgraph.go:167: exec[Package:dnsmasq]: Exited
23:13:31 mgraph.go:167: svc[dnsmasq]: Exited
23:13:31 mgraph.go:167: exec[Package:resolvconf]: Exited
23:13:31 mgraph.go:167: svc[resolvconf]: Exited
23:13:31 mgraph.go:167: noop[completed_Class[Base]]: Exited
23:13:31 mgraph.go:167: noop[completed_Stage[main]]: Exited
23:13:31 etcd.go:454: Etcd: Destroy: Unvolunteering...
23:13:31 etcd.go:1237: Etcd: Members: List: [faalserver]
23:13:31 etcd.go:1260: Etcd: Leader: faalserver
23:13:31 etcd.go:1279: Etcd: Volunteers: []
23:13:31 etcd.go:1283: Etcd: Quitters: [faalserver]
23:13:31 etcd.go:1287: Etcd: Quitters: Shutting down self...
23:13:31 etcd.go:1794: Etcd: ApplyDeltaEvents: Event(DELETE): faalserver
23:13:31 etcd.go:1439: Etcd: Nominated: []
23:13:31 etcd.go:1521: Etcd: DestroyServer...
23:13:31 etcd.go:1761: Etcd: DestroyServer: Destroying...
23:13:32 main.go:376: Main: Converged for 1 seconds, exiting!
23:13:38 etcd.go:1765: Etcd: DestroyServer: Done closing...
23:13:38 etcd.go:1772: Etcd: DestroyServer: Unlocking server...
23:13:38 etcd.go:1794: Etcd: ApplyDeltaEvents: Event(DELETE): faalserver
23:13:38 etcd.go:1611: Etcd: Endpoints: []
23:13:38 etcd.go:661: Etcd: CtxError: Reason: CtxReconnectErr: endpoint list changed
23:13:38 etcd.go:465: Etcd: Destroy: Cancelling 6 operations...
23:13:38 etcd.go:940: Etcd: Exiting loop shortly...
23:13:38 etcd.go:687: Etcd: CtxError: Cancelling 6 operations...
23:13:38 etcd.go:694: Etcd: CtxError: Reconnecting...
23:13:38 etcd.go:324: Etcd: Connect: Endpoints: []
23:13:38 etcd.go:338: Etcd: Connect: CtxError...
23:13:38 etcd.go:340: Etcd: Connect: CtxError: Fatal: exit in progress
23:13:38 etcd.go:778: Etcd: Exiting loop shortly...
23:13:41 etcd.go:787: Etcd: Exiting callback loop!
23:13:41 etcd.go:949: Etcd: Exiting loop!
23:13:41 main.go:843: Goodbye!

[purpleidea]

@ffrank Can you try and reproduce this with the latest git master? It contains a substantive re-write should improve things considerably, or make it much easier to debug if there's still an issue.

Thanks

[ffrank]

Er, I didn't open this one ;p

Wait are you getting your Germans mixed up?

[purpleidea]

@ffrank It was what you had found accidentally during your puppet+mgmt presentation at cfgmgmtcamp...