Bug #1990672 “calico workload status in error due to hook failed...” : Bugs : Calico Charm

Revision history for this message

George Kraft (cynerva) wrote on 2022-09-27:

#1

Interesting. It looks like `calicoctl get node <node-name` returned unexpected output - something in line 1 closed the YAML document. I'm guessing it logged a warning to stderr that got captured[1] and interpreted as a YAML sequence, or something.

Recommended fix:
1. Remove the stderr=STDOUT pipe when calling calicoctl
2. Add debug logging when yaml.parser.ParserError is raised in calicoctl_get so we can see what it failed to parse

[1]: https://github.com/charmed-kubernetes/layer-calico/blob/d6af0785470d3370c3791dc17df51874a87da0db/reactive/calico.py#L619

Changed in charm-calico:
importance:	Undecided → High
status:	New → Triaged

Revision history for this message

Konstantinos Kaskavelis (kaskavel) wrote on 2022-11-21:

#2

Download full text (11.1 KiB)

We have a new occurrence of this one here:

https://solutions.qa.canonical.com/v2/testruns/8147f306-af16-4827-84c4-5c293b99d1c9

Full logs from the run can be found here:

https://oil-jenkins.canonical.com/artifacts/8147f306-af16-4827-84c4-5c293b99d1c9/index.html

From ./7/baremetal/var/log/juju/unit-calico-3.log (in juju-crashdump-kubernetes-aws-2022-11-18-18.59.52.tar.gz)

tracer: hooks phase, 1 handlers queued
tracer: ++ queue handler hooks/relations/etcd/requires.py:24:changed
2022-11-18 18:59:09 INFO unit.calico/3.juju-log server.go:316 etcd:16: Invoking reactive handler: hooks/relations/etcd/requires.py:24:changed
2022-11-18 18:59:09 DEBUG unit.calico/3.juju-log server.go:316 etcd:16: tracer: set flag etcd.connected
2022-11-18 18:59:09 DEBUG unit.calico/3.juju-log server.go:316 etcd:16: tracer: set flag etcd.available
2022-11-18 18:59:09 DEBUG unit.calico/3.juju-log server.go:316 etcd:16: tracer: set flag etcd.tls.available
2022-11-18 18:59:09 DEBUG unit.calico/3.juju-log server.go:316 etcd:16: tracer>
tracer: main dispatch loop, 6 handlers queued
tracer: ++ queue handler hooks/relations/kubernetes-cni/requires.py:49:broken:cni
tracer: ++ queue handler reactive/calico.py:146:update_calicoctl_env
tracer: ++ queue handler reactive/calico.py:161:install_etcd_credentials
tracer: ++ queue handler reactive/calico.py:428:configure_bgp_globals
tracer: ++ queue handler reactive/calico.py:484:configure_node
tracer: ++ queue handler reactive/calico.py:513:configure_bgp_peers
2022-11-18 18:59:09 INFO unit.calico/3.juju-log server.go:316 etcd:16: Invoking reactive handler: reactive/calico.py:146:update_calicoctl_env
2022-11-18 18:59:09 INFO unit.calico/3.juju-log server.go:316 etcd:16: Invoking reactive handler: reactive/calico.py:161:install_etcd_credentials
2022-11-18 18:59:09 DEBUG unit.calico/3.juju-log server.go:316 etcd:16: tracer>
tracer: set flag calico.etcd-credentials.installed
tracer: ++ queue handler reactive/calico.py:308:configure_calico_pool
tracer: -- dequeue handler reactive/calico.py:161:install_etcd_credentials
2022-11-18 18:59:09 INFO unit.calico/3.juju-log server.go:316 etcd:16: Invoking reactive handler: reactive/calico.py:428:configure_bgp_globals
2022-11-18 18:59:09 INFO unit.calico/3.juju-log server.go:316 etcd:16: status-set: maintenance: Configuring BGP globals
2022-11-18 18:59:12 DEBUG juju.worker.uniter.remotestate watcher.go:660 got a relation units change for calico/3 : {16 {map[etcd/2:{1}] map[] []}}
2022-11-18 18:59:18 ERROR unit.calico/3.juju-log server.go:316 etcd:16: Hook error:
Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/charms/reactive/__init__.py", line 74, in main
    bus.dispatch(restricted=restricted_mode)
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 390, in dispatch
    _invoke(other_handlers)
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 359, in _invoke
    handler.invoke()
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 181, in invoke
    se...

We have a new occurrence of this one here:

https://solutions.qa.canonical.com/v2/testruns/8147f306-af16-4827-84c4-5c293b99d1c9

Full logs from the run can be found here:

https://oil-jenkins.canonical.com/artifacts/8147f306-af16-4827-84c4-5c293b99d1c9/index.html

From ./7/baremetal/var/log/juju/unit-calico-3.log (in juju-crashdump-kubernetes-aws-2022-11-18-18.59.52.tar.gz)

tracer: hooks phase, 1 handlers queued
tracer: ++   queue handler hooks/relations/etcd/requires.py:24:changed
2022-11-18 18:59:09 INFO unit.calico/3.juju-log server.go:316 etcd:16: Invoking reactive handler: hooks/relations/etcd/requires.py:24:changed
2022-11-18 18:59:09 DEBUG unit.calico/3.juju-log server.go:316 etcd:16: tracer: set flag etcd.connected
2022-11-18 18:59:09 DEBUG unit.calico/3.juju-log server.go:316 etcd:16: tracer: set flag etcd.available
2022-11-18 18:59:09 DEBUG unit.calico/3.juju-log server.go:316 etcd:16: tracer: set flag etcd.tls.available
2022-11-18 18:59:09 DEBUG unit.calico/3.juju-log server.go:316 etcd:16: tracer>
tracer: main dispatch loop, 6 handlers queued
tracer: ++   queue handler hooks/relations/kubernetes-cni/requires.py:49:broken:cni
tracer: ++   queue handler reactive/calico.py:146:update_calicoctl_env
tracer: ++   queue handler reactive/calico.py:161:install_etcd_credentials
tracer: ++   queue handler reactive/calico.py:428:configure_bgp_globals
tracer: ++   queue handler reactive/calico.py:484:configure_node
tracer: ++   queue handler reactive/calico.py:513:configure_bgp_peers
2022-11-18 18:59:09 INFO unit.calico/3.juju-log server.go:316 etcd:16: Invoking reactive handler: reactive/calico.py:146:update_calicoctl_env
2022-11-18 18:59:09 INFO unit.calico/3.juju-log server.go:316 etcd:16: Invoking reactive handler: reactive/calico.py:161:install_etcd_credentials
2022-11-18 18:59:09 DEBUG unit.calico/3.juju-log server.go:316 etcd:16: tracer>
tracer: set flag calico.etcd-credentials.installed
tracer: ++   queue handler reactive/calico.py:308:configure_calico_pool
tracer: -- dequeue handler reactive/calico.py:161:install_etcd_credentials
2022-11-18 18:59:09 INFO unit.calico/3.juju-log server.go:316 etcd:16: Invoking reactive handler: reactive/calico.py:428:configure_bgp_globals
2022-11-18 18:59:09 INFO unit.calico/3.juju-log server.go:316 etcd:16: status-set: maintenance: Configuring BGP globals
2022-11-18 18:59:12 DEBUG juju.worker.uniter.remotestate watcher.go:660 got a relation units change for calico/3 : {16 {map[etcd/2:{1}] map[] []}}
2022-11-18 18:59:18 ERROR unit.calico/3.juju-log server.go:316 etcd:16: Hook error:
Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/charms/reactive/__init__.py", line 74, in main
    bus.dispatch(restricted=restricted_mode)
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 390, in dispatch
    _invoke(other_handlers)
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 359, in _invoke
    handler.invoke()
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 181, in invoke
    self._action(*args)
  File "/var/lib/juju/agents/unit-calico-3/charm/reactive/calico.py", line 436, in configure_bgp_globals
    bgp_config = calicoctl_get('bgpconfig', 'default')
  File "/var/lib/juju/agents/unit-calico-3/charm/reactive/calico.py", line 685, in calicoctl_get
    result = yaml.safe_load(output)
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/yaml/__init__.py", line 162, in safe_load
    return load(stream, SafeLoader)
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/yaml/__init__.py", line 114, in load
    return loader.get_single_data()
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/yaml/constructor.py", line 49, in get_single_data
    node = self.get_single_node()
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/yaml/composer.py", line 39, in get_single_node
    if not self.check_event(StreamEndEvent):
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/yaml/parser.py", line 98, in check_event
    self.current_event = self.state()
  File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/yaml/parser.py", line 171, in parse_document_start
    raise ParserError(None, None,
yaml.parser.ParserError: expected '<document start>', but found '<block mapping start>'
  in "<byte string>", line 2, column 1:
    apiVersion: projectcalico.org/v3
    ^

2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60 Traceback (most recent call last):
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   File "/var/lib/juju/agents/unit-calico-3/charm/hooks/etcd-relation-joined", line 22, in <module>
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     main()
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/charms/reactive/__init__.py", line 74, in main
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     bus.dispatch(restricted=restricted_mode)
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 390, in dispatch
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     _invoke(other_handlers)
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 359, in _invoke
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     handler.invoke()
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/charms/reactive/bus.py", line 181, in invoke
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     self._action(*args)
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   File "/var/lib/juju/agents/unit-calico-3/charm/reactive/calico.py", line 436, in configure_bgp_globals
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     bgp_config = calicoctl_get('bgpconfig', 'default')
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   File "/var/lib/juju/agents/unit-calico-3/charm/reactive/calico.py", line 685, in calicoctl_get
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     result = yaml.safe_load(output)
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/yaml/__init__.py", line 162, in safe_load
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     return load(stream, SafeLoader)
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/yaml/__init__.py", line 114, in load
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     return loader.get_single_data()
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/yaml/constructor.py", line 49, in get_single_data
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     node = self.get_single_node()
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/yaml/composer.py", line 39, in get_single_node
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     if not self.check_event(StreamEndEvent):
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/yaml/parser.py", line 98, in check_event
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     self.current_event = self.state()
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   File "/var/lib/juju/agents/unit-calico-3/.venv/lib/python3.8/site-packages/yaml/parser.py", line 171, in parse_document_start
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     raise ParserError(None, None,
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60 yaml.parser.ParserError: expected '<document start>', but found '<block mapping start>'
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60   in "<byte string>", line 2, column 1:
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     apiVersion: projectcalico.org/v3
2022-11-18 18:59:18 WARNING unit.calico/3.etcd-relation-joined logger.go:60     ^
2022-11-18 18:59:18 ERROR juju.worker.uniter.operation runhook.go:140 hook "etcd-relation-joined" (via explicit, bespoke hook script) failed: exit status 1
2022-11-18 18:59:18 DEBUG juju.machinelock machinelock.go:202 created rotating log file "/var/log/juju/machine-lock.log" with max size 10 MB and max backups 5
2022-11-18 18:59:18 DEBUG juju.machinelock machinelock.go:186 machine lock released for calico/3 uniter (run relation-joined (16; unit: etcd/0) hook)
2022-11-18 18:59:18 DEBUG juju.worker.uniter.operation executor.go:115 lock released for calico/3
2022-11-18 18:59:18 INFO juju.worker.uniter resolver.go:145 awaiting error resolution for "relation-joined" hook
2022-11-18 18:59:18 DEBUG juju.worker.uniter agent.go:20 [AGENT-STATUS] error: hook failed: "etcd-relation-joined"
2022-11-18 18:59:19 DEBUG juju.worker.meterstatus connected.go:93 got meter status change signal from watcher
2022-11-18 18:59:22 DEBUG juju.worker.uniter.remotestate watcher.go:660 got a relation units change for calico/3 : {16 {map[etcd/1:{2}] map[] []}}
2022-11-18 18:59:22 INFO juju.worker.uniter resolver.go:145 awaiting error resolution for "relation-joined" hook
2022-11-18 18:59:31 DEBUG juju.worker.uniter.remotestate watcher.go:660 got a relation units change for calico/3 : {16 {map[etcd/0:{3}] map[] []}}
2022-11-18 18:59:31 INFO juju.worker.uniter resolver.go:145 awaiting error resolution for "relation-joined" hook
2022-11-18 18:59:36 DEBUG juju.worker.uniter.remotestate watcher.go:660 got a relation units change for calico/3 : {16 {map[etcd/2:{2}] map[] []}}
2022-11-18 18:59:36 INFO juju.worker.uniter resolver.go:145 awaiting error resolution for "relation-joined" hook
2022-11-18 19:00:04 DEBUG juju.worker.uniter.remotestate watcher.go:660 got a relation units change for calico/3 : {16 {map[etcd/1:{3}] map[] []}}
2022-11-18 19:00:04 INFO juju.worker.uniter resolver.go:145 awaiting error resolution for "relation-joined" hook
2022-11-18 19:01:15 DEBUG juju.worker.uniter.remotestate watcher.go:666 update status timer triggered for calico/3
2022-11-18 19:01:15 INFO juju.worker.uniter resolver.go:145 awaiting error resolution for "relation-joined" hook

George Kraft (cynerva) on 2022-11-29

Changed in charm-calico:
milestone:	none → 1.26+ck1
milestone:	1.26+ck1 → 1.26
assignee:	nobody → George Kraft (cynerva)
status:	Triaged → In Progress

Revision history for this message

George Kraft (cynerva) wrote on 2022-11-29:

#3

PR: https://github.com/charmed-kubernetes/layer-calico/pull/94

Kevin W Monroe (kwmonroe) on 2022-11-30

Changed in charm-calico:
status:	In Progress → Fix Committed

Adam Dyess (addyess) on 2022-12-15

Changed in charm-calico:
status:	Fix Committed → Fix Released

Calico Charm

calico workload status in error due to hook failed: "update-status"

Bug Description

Duplicates of this bug

Other bug subscribers

Remote bug watches