Encountered an error running timeconv.parse_rfc3339 in ops.pebble

[shayancanonical]

Issue

When running mysql-k8s, we ran into the following error trace when executing pebble.exec here

unit-mysql-k8s-2: 18:33:53 INFO juju.worker.uniter.operation ran "update-status" hook (via hook dispatching script: dispatch)
unit-mysql-k8s-0: 18:38:01 ERROR unit.mysql-k8s/0.juju-log Uncaught exception while in charm code:
Traceback (most recent call last):
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/./src/charm.py", line 786, in <module>
    main(MySQLOperatorCharm)
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/venv/ops/main.py", line 441, in main
    _emit_charm_event(charm, dispatcher.event_name)
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/venv/ops/main.py", line 149, in _emit_charm_event
    event_to_emit.emit(*args, **kwargs)
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/venv/ops/framework.py", line 342, in emit
    framework._emit(event)
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/venv/ops/framework.py", line 839, in _emit
    self._reemit(event_path)
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/venv/ops/framework.py", line 928, in _reemit
    custom_handler(event)
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/src/rotate_mysql_logs.py", line 57, in _rotate_mysql_logs
    self.charm._mysql.flush_mysql_logs(MySQLTextLogs.SLOW)
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/lib/charms/mysql/v0/mysql.py", line 2585, in flush_mysql_logs
    self._run_mysqlsh_script("\n".join(flush_logs_commands))
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/src/mysql_k8s_helpers.py", line 666, in _run_mysqlsh_script
    stdout, _ = process.wait_output()
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/venv/ops/pebble.py", line 1354, in wait_output
    exit_code: int = self._wait()
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/venv/ops/pebble.py", line 1294, in _wait
    change = self._client.wait_change(self._change_id, timeout=timeout)
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/venv/ops/pebble.py", line 1794, in wait_change
    return self._wait_change_using_wait(change_id, timeout)
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/venv/ops/pebble.py", line 1815, in _wait_change_using_wait
    return self._wait_change(change_id, this_timeout)
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/venv/ops/pebble.py", line 1837, in _wait_change
    return Change.from_dict(resp['result'])
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/venv/ops/pebble.py", line 670, in from_dict
    spawn_time=timeconv.parse_rfc3339(d['spawn-time']),
  File "/var/lib/juju/agents/unit-mysql-k8s-0/charm/venv/ops/_private/timeconv.py", line 54, in parse_rfc3339
    return datetime.datetime(int(y), int(m), int(d), int(hh), int(mm), int(ss),
ValueError: microsecond must be in 0..999999
unit-mysql-k8s-0: 18:38:01 INFO juju.util.exec run result: exit status 1

Versions

juju: 3.1.6
ops: 2.5.1

Steps to Reproduce

juju deploy mysql-k8s --trust --channel 8.0/edge -n 3
# wait for weekend...

References

Discovered and documented in the following MySQL K8s Jira ticket

[tonyandrewmeyer]

Maybe this is the rounding issue, and just very unlucky to be in exactly the wrong part of a second? e.g.

>>> timeconv.parse_rfc3339("2006-08-28T13:20:00.9999991+12:00")
datetime.datetime(2006, 8, 28, 13, 20, 0, 999999, tzinfo=datetime.timezone(datetime.timedelta(seconds=43200)))
>>> timeconv.parse_rfc3339("2006-08-28T13:20:00.9999999+12:00")
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/home/tameyer/code/operator/ops/_private/timeconv.py", line 54, in parse_rfc3339
    return datetime.datetime(int(y), int(m), int(d), int(hh), int(mm), int(ss),
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
ValueError: microsecond must be in 0..999999

I assume we ought to be either truncating or if the rounding takes the microseconds > 1s then carrying that over to the second value. Fwiw, it looks like the standard lib truncates (we could potentially use the stdlib method if running under Python 3.11+).

@shayancanonical any idea if this reproducible (particularly without the "wait for weekend" 😆)? If this is the above issue then you'd expect that it only occurred very rarely.

[shayancanonical]

@tonyandrewmeyer Thanks for the explanation on the possible cause of the issue. It is very hard to reproduce if it is really that rare, and we have found no other such traces in our testing. I have currently set up an environment to test the log rotation error, and will inform here if the above trace pops up again, but I am not expecting it to due to the rarity of the circumstances

[tonyandrewmeyer]

Thanks! It's definitely one way that this could happen (so should be fixed anyway). It's tricky to say for sure that it was what happened in this case - in theory Juju could have returned some sort of invalid time - without being able to reproduce or having the data from when it did. It seems reasonable to assume that this is the cause, though.