ovn-chassis failing hooks post-deploy when dpdk enabled with deferred restarts

[Paul Goins]

Affected charm: ovn-chassis rev 109, channel 22.09/stable, version 8f25774
Target OS: 22.04 Jammy

Expected behavior: When deployed as a subordinate to nova-compute, with appropriate kernel options set in advance for hugepages, the compute deploys and the ovn-chassis charm does not have any failing hooks. If restarts were needed, the ovn-chassis charm should go into a blocked state indicating such.

Observed behavior: on all 4 computes I recently tried, every one of them starts to get failing ovn-chassis hooks.

Observed traceback from the Juju unit log:

2024-01-09 22:58:44 INFO unit.ovn-chassis/41.juju-log server.go:316 ovsdb:361: Invoking reactive handler: hooks/relations/ovsdb-subordinate/provides.py:130:broken:ovsdb-subordinate
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 Traceback (most recent call last):
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 File "/var/lib/juju/agents/unit-ovn-chassis-41/charm/hooks/ovsdb-relation-joined", line 22, in <module>
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 main()
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 File "/var/lib/juju/agents/unit-ovn-chassis-41/.venv/lib/python3.10/site-packages/charms/reactive/__init__.py", line 84, in main
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 hookenv._run_atexit()
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 File "/var/lib/juju/agents/unit-ovn-chassis-41/.venv/lib/python3.10/site-packages/charmhelpers/core/hookenv.py", line 1357, in _run_atexit
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 callback(*args, **kwargs)
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 File "/var/lib/juju/agents/unit-ovn-chassis-41/.venv/lib/python3.10/site-packages/charms_openstack/charm/core.py", line 1378, in atexit_assess_status
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 self._assess_status()
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 File "/var/lib/juju/agents/unit-ovn-chassis-41/.venv/lib/python3.10/site-packages/charms_openstack/charm/core.py", line 1360, in _assess_status
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 state, message = f()
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 File "/var/lib/juju/agents/unit-ovn-chassis-41/charm/lib/charms/ovn_charm.py", line 136, in custom_assess_status_check
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 deferred_events.check_restart_timestamps()
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 File "/var/lib/juju/agents/unit-ovn-chassis-41/.venv/lib/python3.10/site-packages/charmhelpers/contrib/openstack/deferred_events.py", line 358, in check_restart_timestamps
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 start_time = get_service_start_time(event.service)
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 File "/var/lib/juju/agents/unit-ovn-chassis-41/.venv/lib/python3.10/site-packages/charmhelpers/contrib/openstack/deferred_events.py", line 345, in get_service_start_time
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 start_time = datetime.datetime.strptime(
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 File "/usr/lib/python3.10/_strptime.py", line 568, in _strptime_datetime
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 tt, fraction, gmtoff_fraction = _strptime(data_string, format)
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 File "/usr/lib/python3.10/_strptime.py", line 349, in _strptime
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 raise ValueError("time data %r does not match format %r" %
2024-01-09 22:58:44 WARNING unit.ovn-chassis/41.ovsdb-relation-joined logger.go:60 ValueError: time data 'n/a' does not match format '%a %Y-%m-%d %H:%M:%S %Z'
2024-01-09 22:58:45 ERROR juju.worker.uniter.operation runhook.go:153 hook "ovsdb-relation-joined" (via explicit, bespoke hook script) failed: exit status 1

Upon deeper analysis, this appears to be a possible bug in charmhelpers/contrib/openstack/deferred_events.py, in the get_service_start_time function. That function tries to parse the output of "systemctl show dpdk --property=ActiveEnterTimestamp" (as the dpdk service had a deferred restart, but encountered the string "n/a" since it had never been started, which is unexpected by the code and causes the error.

While this affects the specific ovn-chassis charm as described above, the actual bug appears to be in charmhelpers; I will add that project to this bug as well.

[Paul Goins (vultaire)]

charm-helpers is on github; I will create an issue there regarding this.

[Paul Goins (vultaire)]

Related github bug: https://github.com/juju/charm-helpers/issues/873

[Alex Kavanagh (ajkavanagh)]

Paul, this project is in the bizarre state of having both launchpad and github bugs. We really ought to settle on one of the sites for bugs, and I tend to think that it's more useful to keep the bugs here, than put them on github. However, the code is on github which means that the bugs should probably live there. Dilemma.

[Paul Goins (vultaire)]

I'm fine having both bugs here - but https://launchpad.net/charm-helpers explicitly says "THIS PROJECT HAS MOVED TO https://github.com/juju/charm-helpers", which discouraged me from filing a bug there.

[Alex Kavanagh (ajkavanagh)]

> I'm fine having both bugs here - but https://launchpad.net/charm-helpers explicitly says "THIS PROJECT HAS MOVED TO https://github.com/juju/charm-helpers", which discouraged me from filing a bug there.

Yes, I agree it is a bit "don't file it here". I only linked it so this bug also shows there's an issue in charm-helpers; but it looks like this bug is watching the github one now due to you posting the link in #2.