| 2022-11-01 15:47:28 |
Vadik Mironov |
description |
This issue started since 22.04, but only after upgrade to 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 22.04/10, the session time that timekpr reports goes to 00:00 and he stays logged in with apparent actions taken by the timekpr daemon. 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) |
This issue started since 22.04, but only after upgrade to 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 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) |
|
