Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

systemd: ensure we only iterate over timers #403

Closed
wants to merge 1 commit into from

Conversation

Flowdalic
Copy link

@Flowdalic Flowdalic commented Aug 9, 2023

Somehow the loop contained

(Pdb) p props
dbus.Dictionary({dbus.String('Unit'): dbus.String('cron-monthly.target', variant_level=1), dbus.String('TimersMonotonic'): dbus.Array([], signature=dbus.Signature('(stt)'), variant_level=1), dbus.String('TimersCalendar'): dbus.Array([dbus.Struct((dbus.String('OnCalendar'), dbus.String('*-*-01 00:00:00'), dbus.UInt64(0)), signature=None)], signature=dbus.Signature('(sst)'), variant_level=1), dbus.String('OnClockChange'): dbus.Boolean(False, variant_level=1), dbus.String('OnTimezoneChange'): dbus.Boolean(False, variant_level=1), dbus.String('NextElapseUSecRealtime'): dbus.UInt64(18446744073709551615, variant_level=1), dbus.String('NextElapseUSecMonotonic'): dbus.UInt64(18446744073709551615, variant_level=1),

that is, cron-montly.target, with NextElapseUSecRealtime and NextElapseUSecMonotonic set to 18446744073709551615 (UINT64_MAX).

This caused datetime.fromtimestamp() to throw a ValueError, causing the termination of autosuspend:

autosuspend[7204]: 2023-08-09 14:08:09,920 - autosuspend.Processor - INFO - System is idle long enough.
autosuspend[7204]: Traceback (most recent call last):
autosuspend[7204]:   File "/usr/lib/python-exec/python3.11/autosuspend", line 8, in <module>
autosuspend[7204]:     sys.exit(main())
autosuspend[7204]:              ^^^^^^
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 793, in main
autosuspend[7204]:     args.func(args, config)
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 775, in main_daemon
autosuspend[7204]:     loop(
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 375, in loop
autosuspend[7204]:     _do_loop_iteration(processor, woke_up_file, lock_file, lock_timeout)
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 340, in _do_loop_iteration
autosuspend[7204]:     processor.iteration(datetime.now(timezone.utc), just_woke_up)
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 283, in iteration
autosuspend[7204]:     wakeup_at = execute_wakeups(self._wakeups, timestamp, self._logger)
autosuspend[7204]:                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 168, in execute_wakeups
autosuspend[7204]:     this_at = _safe_execute_wakeup(wakeup, timestamp, logger)
autosuspend[7204]:               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 157, in _safe_execute_wakeup
autosuspend[7204]:     return check.check(timestamp)
autosuspend[7204]:            ^^^^^^^^^^^^^^^^^^^^^^
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/checks/systemd.py", line 57, in check
autosuspend[7204]:     executions = next_timer_executions()
autosuspend[7204]:                  ^^^^^^^^^^^^^^^^^^^^^^^
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/checks/systemd.py", line 27, in next_timer_executions
autosuspend[7204]:     next_time = datetime.fromtimestamp(
autosuspend[7204]:                 ^^^^^^^^^^^^^^^^^^^^^^^
autosuspend[7204]: ValueError: year 586524 is out of range
systemd[1]: autosuspend.service: Main process exited, code=exited, status=1/FAILURE
systemd[1]: autosuspend.service: Failed with result 'exit-code'.

To avoid this, we check that the unit we look at is actually a timer.

Somehow the loop contained

(Pdb) p props
dbus.Dictionary({dbus.String('Unit'): dbus.String('cron-monthly.target', variant_level=1), dbus.String('TimersMonotonic'): dbus.Array([], signature=dbus.Signature('(stt)'), variant_level=1), dbus.String('TimersCalendar'): dbus.Array([dbus.Struct((dbus.String('OnCalendar'), dbus.String('*-*-01 00:00:00'), dbus.UInt64(0)), signature=None)], signature=dbus.Signature('(sst)'), variant_level=1), dbus.String('OnClockChange'): dbus.Boolean(False, variant_level=1), dbus.String('OnTimezoneChange'): dbus.Boolean(False, variant_level=1), dbus.String('NextElapseUSecRealtime'): dbus.UInt64(18446744073709551615, variant_level=1), dbus.String('NextElapseUSecMonotonic'): dbus.UInt64(18446744073709551615, variant_level=1),

that is, cron-montly.target, with NextElapseUSecRealtime and
NextElapseUSecMonotonic set to 18446744073709551615 (UINT64_MAX).

This caused datetime.fromtimestamp() to throw a ValueError, causing
the termination of autosuspend:

autosuspend[7204]: 2023-08-09 14:08:09,920 - autosuspend.Processor - INFO - System is idle long enough.
autosuspend[7204]: Traceback (most recent call last):
autosuspend[7204]:   File "/usr/lib/python-exec/python3.11/autosuspend", line 8, in <module>
autosuspend[7204]:     sys.exit(main())
autosuspend[7204]:              ^^^^^^
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 793, in main
autosuspend[7204]:     args.func(args, config)
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 775, in main_daemon
autosuspend[7204]:     loop(
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 375, in loop
autosuspend[7204]:     _do_loop_iteration(processor, woke_up_file, lock_file, lock_timeout)
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 340, in _do_loop_iteration
autosuspend[7204]:     processor.iteration(datetime.now(timezone.utc), just_woke_up)
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 283, in iteration
autosuspend[7204]:     wakeup_at = execute_wakeups(self._wakeups, timestamp, self._logger)
autosuspend[7204]:                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 168, in execute_wakeups
autosuspend[7204]:     this_at = _safe_execute_wakeup(wakeup, timestamp, logger)
autosuspend[7204]:               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/__init__.py", line 157, in _safe_execute_wakeup
autosuspend[7204]:     return check.check(timestamp)
autosuspend[7204]:            ^^^^^^^^^^^^^^^^^^^^^^
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/checks/systemd.py", line 57, in check
autosuspend[7204]:     executions = next_timer_executions()
autosuspend[7204]:                  ^^^^^^^^^^^^^^^^^^^^^^^
autosuspend[7204]:   File "/usr/lib/python3.11/site-packages/autosuspend/checks/systemd.py", line 27, in next_timer_executions
autosuspend[7204]:     next_time = datetime.fromtimestamp(
autosuspend[7204]:                 ^^^^^^^^^^^^^^^^^^^^^^^
autosuspend[7204]: ValueError: year 586524 is out of range
systemd[1]: autosuspend.service: Main process exited, code=exited, status=1/FAILURE
systemd[1]: autosuspend.service: Failed with result 'exit-code'.

To avoid this, we check that the unit we look at is actually a timer.
@languitar languitar changed the title systemd: ensure we only iteratore over timers systemd: ensure we only iterate over timers Aug 10, 2023
@languitar
Copy link
Owner

I don't understand how this condition can actually happen. In line 17 only units ending with .timer are requested. How that change to something with name *.target?

@Flowdalic
Copy link
Author

I don't understand how this condition can actually happen. In line 17 only units ending with .timer are requested. How that change to something with name *.target?

I wondered myself the same and do not have an answer. I guess it is related to to semantic of the invocation in line 22.

The only clue I have is that the returned object is from cron-monthly.target which is related to cron-monthly.timer. You may be able to reproduce it by installing and activating systemd-cron, where cron-monhtly.{target|timer} originates from.

@languitar
Copy link
Owner

Good catch, I don't have systemd-cron installed. I'll have a look on why that happens. Thanks for finding this and providing a PR in any case.

languitar added a commit that referenced this pull request Aug 10, 2023
Systemd has a concept of timers running after a specified amount of time
after boot but without recurrence. Therefore, these timers might not
have a next execution time attached as they already executed after boot.
In these cases, the fields containing next execution timers are all set
to UINT64 max value to indicate their absence. This weird special case
was not covered so far and the maximum value was interpreted as a usual
time information.

Fixes #403
@languitar
Copy link
Owner

Alright, I have found the real culprit behind this. System knows timers that execute after a defined amount of time after system boot. Afterwards, they never execute again. The unbelievably large value interpreted as the next execution time here is dbus' way of telling, that no further execution is planned. In this case, the next execution time fields are all set to UINT64 max value. systemd-cron includes a boot target that triggers this error condition. #406 contains a proper fix for this condition that is not based on the unit name but absence of next executions to work generally.

@languitar languitar closed this Aug 10, 2023
github-actions bot pushed a commit that referenced this pull request Aug 10, 2023
## [4.3.3](v4.3.2...v4.3.3) (2023-08-10)

### Bug Fixes

* **systemd:** handle timers without next execution time ([9fb83ea](9fb83ea)), closes [#403](#403)
@github-actions
Copy link

🎉 This issue has been resolved in version 4.3.3 🎉

The release is available on GitHub release

Your semantic-release bot 📦🚀

@Flowdalic Flowdalic deleted the systemd-minus-one branch September 27, 2023 07:57
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants