Error is thrown in timekpr logs on user session start and upon user limit reached with user staying logged in

[Vadik Mironov]

[duplicate of https://bugs.launchpad.net/ubuntu/+source/timekpr-next/+bug/1995404]

This issue started since Ubuntu 22.04, but only after upgrade to Ubuntu 22.10 I've managed to cleanly catch it.

My son's user account is configured for 1.5 hours daily. After the migration to Ubuntu 22.04/10, the session time that timekpr reports goes to 00:00 and he stays logged in with no apparent actions taken by the timekpr daemon (unlike previous versions where he was force logged out). To better reproduce it, I've decreased his daily limit down to 3 minutes and upon him logging in, following was printed in the /var/log/timekpr.log:

2022-11-01 14:30:40.558433: --- start working on users ---
2022-11-01 14:30:40.559015: USER: gdm, UID: 126, UNAME: gdm, UPATH: /org/freedesktop/login1/user/_126
2022-11-01 14:30:40.559038: USER: my_son_user_id, UID: 1000, UNAME: my_son_user_id, UPATH: /org/freedesktop/login1/user/_1000
2022-11-01 14:30:40.559058: NOTE: system user "gdm" explicitly excluded
2022-11-01 14:30:40.559077: NOTE: we have a new user "my_son_user_id"
2022-11-01 14:30:40.559088: start init timekprUser
2022-11-01 14:30:40.562758: init user (my_son_user_id) configuration manager
2022-11-01 14:30:40.562910: finish user configuration manager
2022-11-01 14:30:40.562925: init user (my_son_user_id) control
2022-11-01 14:30:40.563003: finish init user control
2022-11-01 14:30:40.563014: start init notifications
2022-11-01 14:30:40.563054: finish init notifications
2022-11-01 14:30:40.563062: finish init timekprUser
2022-11-01 14:30:40.563098: start load user configuration
2022-11-01 14:30:40.563689: PT: found total 0 activities, valid 0
2022-11-01 14:30:40.563721: finish load user configuration
2022-11-01 14:30:40.564963: start loading user control (my_son_user_id)
2022-11-01 14:30:40.565332: finish loading user control
2022-11-01 14:30:40.565408: ---=== start isUserActive for "my_son_user_id" ===---
2022-11-01 14:30:40.566122: user stats, state: active, idleState: False
2022-11-01 14:30:40.566749: adding session: 17, /org/freedesktop/login1/session/_317
2022-11-01 14:30:40.569552: INFO: session locked state is available and will be used for idle state detection (if it works)
2022-11-01 14:30:40.569591: got session - type: wayland, VTNr: 2, state: active, idle: False, locked: False
2022-11-01 14:30:40.569609: session 17 active
2022-11-01 14:30:40.569618: ---=== finish isUserActive: True ===---
2022-11-01 14:30:40.569773: get time for "my_son_user_id", tltd 180, tlrow: 180, tspbal: 0, tspbt: 0, tidbt: 0
2022-11-01 14:30:40.569855: sending tln: 180
2022-11-01 14:30:40.569878: ---=== ERROR working on users ===---
2022-11-01 14:30:40.574737: Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 133, in executeTimekprWorker
    self.checkUsers()
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 258, in checkUsers
    timeLeftArray = self._timekprUserList[rUserName].getTimeLeft()
  File "/usr/lib/python3/dist-packages/timekpr/server/user/userdata.py", line 603, in getTimeLeft
    self._timekprUserNotification.processTimeLeft(pForceNotifications, timeValues)
  File "/usr/lib/python3/dist-packages/timekpr/common/utils/notifications.py", line 139, in processTimeLeft
    self.timeLeftNotification(notifUrgency, max(pTimeValues[cons.TK_CTRL_LEFT], 0), max(pTimeValues[cons.TK_CTRL_LEFTD], 0), pTimeValues[cons.TK_CTRL_LIMITD])
  File "/usr/lib/python3/dist-packages/dbus/decorators.py", line 325, in emit_signal
    message.append(signature=signature, *args)
TypeError: 'float' object cannot be interpreted as an integer

2022-11-01 14:30:40.574777: ---=== ERROR working on users ===---
2022-11-01 14:30:40.575475: --- end working on users (ela: 0:00:00.017038) ---

after that timekpr keeps waking up every 3 seconds with fields tltd and tlrow decremented on every isUserActive call (I assume these are in seconds). After about 120 seconds, it raises a second similar error:

022-11-01 14:32:43.638426: --- start working on users ---
2022-11-01 14:32:43.639181: USER: my_son_user_id, UID: 1000, UNAME: my_son_user_id, UPATH: /org/freedesktop/login1/user/_1000
2022-11-01 14:32:43.639328: ---=== start isUserActive for "my_son_user_id" ===---
2022-11-01 14:32:43.640224: user stats, state: active, idleState: False
2022-11-01 14:32:43.640688: session already cached: 17
2022-11-01 14:32:43.641699: got session - type: wayland, VTNr: 2, state: active, idle: False, locked: False
2022-11-01 14:32:43.641722: session 17 active
2022-11-01 14:32:43.641731: ---=== finish isUserActive: True ===---
2022-11-01 14:32:43.641892: get time for "my_son_user_id", tltd 57, tlrow: 57, tspbal: 123, tspbt: 123, tidbt: 0
2022-11-01 14:32:43.641972: sending tln: 57
2022-11-01 14:32:43.641995: ---=== ERROR working on users ===---
2022-11-01 14:32:43.642137: Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 133, in executeTimekprWorker
    self.checkUsers()
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 258, in checkUsers
    timeLeftArray = self._timekprUserList[rUserName].getTimeLeft()
  File "/usr/lib/python3/dist-packages/timekpr/server/user/userdata.py", line 603, in getTimeLeft
    self._timekprUserNotification.processTimeLeft(pForceNotifications, timeValues)
  File "/usr/lib/python3/dist-packages/timekpr/common/utils/notifications.py", line 139, in processTimeLeft
    self.timeLeftNotification(notifUrgency, max(pTimeValues[cons.TK_CTRL_LEFT], 0), max(pTimeValues[cons.TK_CTRL_LEFTD], 0), pTimeValues[cons.TK_CTRL_LIMITD])
  File "/usr/lib/python3/dist-packages/dbus/decorators.py", line 325, in emit_signal
    message.append(signature=signature, *args)
TypeError: 'float' object cannot be interpreted as an integer

2022-11-01 14:32:43.642148: ---=== ERROR working on users ===---
2022-11-01 14:32:43.642173: --- end working on users (ela: 0:00:00.003764) ---

and this is it - session never kicked out and continues to run until he logs out himself. In the logs, timekeeper continues to report him, but no actions are taken:

022-11-01 14:41:19.986400: --- start working on users ---
2022-11-01 14:41:19.987148: USER: my_son_user_id, UID: 1000, UNAME: my_son_user_id, UPATH: /org/freedesktop/login1/user/_1000
2022-11-01 14:41:19.987241: ---=== start isUserActive for "my_son_user_id" ===---
2022-11-01 14:41:19.988353: user stats, state: active, idleState: False
2022-11-01 14:41:19.988835: session already cached: 17
2022-11-01 14:41:19.989923: got session - type: wayland, VTNr: 2, state: active, idle: False, locked: False
2022-11-01 14:41:19.989963: session 17 active
2022-11-01 14:41:19.989980: ---=== finish isUserActive: True ===---
2022-11-01 14:41:19.990205: get time for "my_son_user_id", tltd 0, tlrow: 0, tspbal: 639, tspbt: 639, tidbt: 0
2022-11-01 14:41:19.990330: time left, tlrow: 0, tleftd: 0, tlimd: 180, notification lvl: 1, priority: critical, force: False
2022-11-01 14:41:19.990381: user "my_son_user_id", active: True/True/False (act/eff/lck), huacc: False, tleft: 0
2022-11-01 14:41:19.990425: --- end working on users (ela: 0:00:00.004031) ---
2022-11-01 14:41:19.990455: --- perf: avg ela: 0:00:00.001387, loadavg: 2.72705078125, 3.3466796875, 2.03125 ---

ProblemType: Bug
DistroRelease: Ubuntu 22.10
Package: timekpr-next 0.5.2-1
ProcVersionSignature: Ubuntu 5.19.0-23.24-generic 5.19.7
Uname: Linux 5.19.0-23-generic x86_64
NonfreeKernelModules: zfs zunicode zavl icp zcommon znvpair
ApportVersion: 2.23.1-0ubuntu3
Architecture: amd64
CasperMD5CheckResult: unknown
CurrentDesktop: ubuntu:GNOME
Date: Tue Nov 1 15:29:24 2022
InstallationDate: Installed on 2021-01-01 (669 days ago)
InstallationMedia: Ubuntu 20.10 "Groovy Gorilla" - Release amd64 (20201022)
ProcEnviron:
 LANGUAGE=en_GB:en
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=en_GB.UTF-8
 SHELL=/bin/bash
SourcePackage: timekpr-next
UpgradeStatus: Upgraded to kinetic on 2022-10-22 (10 days ago)

[Eduards Bezverhijs (mjasnik)]

This issue was spotted and fixed in the beginning of this year after a python version update in some linux distributions.
The fix is incorporated in 0.5.3+ version of timekpr which is not yet packaged in debian and as a result not in ubuntu too.

Please install version from my PPA, latest at this point is 0.5.4 and this should fix it.

Pls report back whether it's all ok.

[Eduards Bezverhijs (mjasnik)]

Did the ppa version solve the issue?

I'll try to ask debian package maintainer to package newest version as it seems that this is starting to affect newer ubuntu versions.

[Vadik Mironov (vadikmironov)]

Eduards, yes, it did. Works like a charm. Please do let me know if there is anything I can help with to trigger the update of ubuntu package in the kinetic repo.

[Eduards Bezverhijs (mjasnik)]

I sent a message to debian package maintainer to update timekpr to latest version.

If there is a need for a patch, I can make it (it's git anyway), but I don't know the procedure how to patch ubuntu official package.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.