programs not terminated

[Authmane Terki]

Hello, in the attached screenshot, you can see that what is called "playtime" is finished but some processes are still running.

Here's part of the log:

"""
2021-03-05 17:41:41.030460: PT stats, users: 1, cache: 328, add: 0, rm: 3, lost: 0, nocmd: 0, qc: 1, changed: 0, admatch: 0
2021-03-05 17:41:41.030598: start adjustTimeSpentActual
2021-03-05 17:41:41.030633: ---=== start isUserActive for "authmane512" ===---
2021-03-05 17:41:41.031775: user stats, state: active, idleState: False
2021-03-05 17:41:41.032365: session already cached: c8
2021-03-05 17:41:41.032398: session already cached: 50
2021-03-05 17:41:41.033858: got session - type: tty, VTNr: 2, state: online, idle: True, locked: False
2021-03-05 17:41:41.033905: session 50 not tracked
2021-03-05 17:41:41.035275: got session - type: x11, VTNr: 7, state: active, idle: False, locked: False
2021-03-05 17:41:41.035320: session c8 active
2021-03-05 17:41:41.035339: ---=== finish isUserActive: True ===---
2021-03-05 17:41:41.035378: PT: user "authmane512" (1000) has 1 matching processes out of 151, using 3 filters
2021-03-05 17:41:41.035415: finish adjustTimeSpentActual
2021-03-05 17:41:41.035520: start getTimeLeft
2021-03-05 17:41:41.035745: get time for "authmane512", tltd 13699.0, tlrow: 13699.0, tspbt: 19784.0, tidbt: 84.0
2021-03-05 17:41:41.035786: start processTimeLeft
2021-03-05 17:41:41.035924: time left, tlrow: 13699, tleftd: 13699, tlimd: 86400, notification lvl: 0, priority: low, force: False
2021-03-05 17:41:41.035942: finish processTimeLeft
2021-03-05 17:41:41.035959: finish getTimeLeft
2021-03-05 17:41:41.035991: PT: user "authmane512" (1000) has 1 matching processes out of 151, using 3 filters
2021-03-05 17:41:41.036012: get PlayTime for "authmane512", ena: True, acc: True, tim: -3813.0
2021-03-05 17:41:41.036032: killing 1 PT processes for uid "1000"
2021-03-05 17:41:41.036054: ---=== ERROR working on users ===---
2021-03-05 17:41:41.036214: Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 132, in executeTimekprWorker
    self.checkUsers()
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 274, in checkUsers
    self._timekprPlayTimeConfig.killPlayTimeProcesses(self._timekprUserList[rUserName].getUserId())
  File "/usr/lib/python3/dist-packages/timekpr/server/user/playtime.py", line 439, in killPlayTimeProcesses
    self._cachedPids[self._PIDS][rPid][self._TERM] += 1
KeyError: '20154'

2021-03-05 17:41:41.036234: ---=== ERROR working on users ===---
2021-03-05 17:41:41.036297: --- end working on users (ela: 0:00:00.008288) ---
2021-03-05 17:41:41.036326: --- perf: avg ela: 0:00:00.009096, loadavg: 1.64, 0.86, 0.9 ---
2021-03-05 17:41:44.031077: --- start working on users ---
2021-03-05 17:41:44.031135: start checkUsers
2021-03-05 17:41:44.031161: start getUserList
2021-03-05 17:41:44.031707: USER: authmane512, UID: 1000, UNAME: authmane512, UPATH: /org/freedesktop/login1/user/_1000
"""

Could you help me? Thanks!

[Eduards Bezverhijs (mjasnik)]

Yes, I can, but please add whole log file to the bug report, so I can see what happens some time before and some time after this.

[Eduards Bezverhijs (mjasnik)]

I found the possibility why this happens, it's rather odd, but still a possibility.
I have a tentative fix for this, but I would like to verify the cause before releasing a fix, for that I need a log file.

[Eduards Bezverhijs (mjasnik)]

Tentative fix is available in beta version.

[Eduards Bezverhijs (mjasnik)]

Fix is released to stable too. Hopefully it helps.

[Authmane Terki (authmaneterki)]

Thank you very much for your fast answer!!!

I attached a big log file. :-)

In it you can find these errors:

======
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 132, in executeTimekprWorker
    self.checkUsers()
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 274, in checkUsers
    self._timekprPlayTimeConfig.killPlayTimeProcesses(self._timekprUserList[rUserName].getUserId())
  File "/usr/lib/python3/dist-packages/timekpr/server/user/playtime.py", line 439, in killPlayTimeProcesses
    self._cachedPids[self._PIDS][rPid][self._TERM] += 1
KeyError: '20154'
======

======
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 135, in executeTimekprWorker
    self.checkUsers()
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 191, in checkUsers
    self._timekprPlayTimeConfig.processPlayTimeActivities()
  File "/usr/lib/python3/dist-packages/timekpr/server/user/playtime.py", line 328, in processPlayTimeActivities
    self._cachePlayTimeProcesses()
  File "/usr/lib/python3/dist-packages/timekpr/server/user/playtime.py", line 264, in _cachePlayTimeProcesses
    self._cachedPids[self._USRS][userId][self._PIDS].add(procId)
KeyError: None
======

======
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 132, in executeTimekprWorker
    self.checkUsers()
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 251, in checkUsers
    userActiveEffective, userActiveActual, userScreenLocked = self._timekprUserList[rUserName].adjustTimeSpentActual(self._timekprConfig)
  File "/usr/lib/python3/dist-packages/timekpr/server/user/userdata.py", line 533, in adjustTimeSpentActual
    self.saveSpent()
  File "/usr/lib/python3/dist-packages/timekpr/server/user/userdata.py", line 642, in saveSpent
    self.adjustTimeSpentFromControl(pSilent=False, pPreserveSpent=True)
  File "/usr/lib/python3/dist-packages/timekpr/server/user/userdata.py", line 362, in adjustTimeSpentFromControl
    timeSpentBeforeReload = max(self._timekprUserData[self._currentDOW][cons.TK_CTRL_SPENTBD] - self._timekprUserControl.getUserTimeSpentBalance(), 0)
  File "/usr/lib/python3/dist-packages/timekpr/common/utils/config.py", line 1331, in getUserTimeSpentBalance
    return self._timekprUserControl["TIME_SPENT_BALANCE"]
KeyError: 'TIME_SPENT_BALANCE'
======

======
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 132, in executeTimekprWorker
    self.checkUsers()
  File "/usr/lib/python3/dist-packages/timekpr/server/interface/dbus/daemon.py", line 274, in checkUsers
    self._timekprPlayTimeConfig.killPlayTimeProcesses(self._timekprUserList[rUserName].getUserId())
  File "/usr/lib/python3/dist-packages/timekpr/server/user/playtime.py", line 439, in killPlayTimeProcesses
    self._cachedPids[self._PIDS][rPid][self._TERM] += 1
KeyError: '29706'
======

Thank you again!

[Eduards Bezverhijs (mjasnik)]

The original issue should be fixed and that was caused by snap/flatpak "packages", which I personally and my beta testers do not use, thus it has not been field tested.

Please update the timekpr and the issue should go away.

Other than that, you had permissions issues outside timekpr. These issues may generate multiple other errors like you mentioned above.

Please use the updated timekpr and report back whether the issues went away or they are still there.
If they are still there, please attach updated log file.

[Authmane Terki (authmaneterki)]

Thank you for your answer.

You said that I had permissions issues? Which ones?

I updated timekpr-next, I'll see if the problem has gone away, if so I'll write a message here.

By the way, you said there are issues with snap/flatpak packages. I think I have another problem with them: these programs are not detected by timekpr. But I found as a workaround to use these masks:
.*opera.*
.*freetube.*
.*dolphin-emu.*

I installed opera with snap, and freetube and dolphin-emu with flatpak. If I only use "opera", "freetube" or "dolphin-emu", timekpr doesn't detect the programs. You see?

I think that's a problem (isn't it?), because as you said in your documentation, using regex masks is sensitive.

[Eduards Bezverhijs (mjasnik)]

The permission issue I'm referring to is this (occurred: 2021-03-04 12:03:42.626887):
----------------------------
    with open(self._configFile, "w") as fp:
PermissionError: [Errno 1] Operation not permitted: '/var/lib/timekpr/config/timekpr.authmane512.conf'
----------------------------

Because of this it was not possible to write to config file and read it afterwards, that caused other errors.
After some some, after the log file was cut (2021-03-04 12:36:47.084534), there are no more errors, so permission issue went away.

As for program detection, there is no magic in detecting programs in timekpr, it just checks the process names and additionally parameters, if "Enhanced activity monitor" is enabled.

If the mask is "opera", then it matches everything that ends with "opera", that is: /some/path/to/opera, but the following will not work: /some/path/to/opera-browser., however they will both match, if mask is "·*opera.*".

In the log files there are a lines:
----------------------------
2021-03-05 09:14:04.037963: PT match, uid: 1000, exe: /snap/opera/112/usr/lib/x86_64-linux-gnu/opera/opera, cmdl: n/a
2021-03-05 09:14:16.052033: PT: user "authmane512" (1000) has 44 matching processes out of 173, using 3 filters
----------------------------

But I don't know whether that's with regexp or without.

I'll try to install opera in VM to check how opera behaves as snap/flatpak. Process monitor was tested on standard processes only, but snap/flatpak packages are getting more popular, so it's time to check it out :)

[Eduards Bezverhijs (mjasnik)]

Just tested, on my VM with Ubuntu 18.04, installing opera via snap works fine with simple mask "opera".

Process names are the same as in your situation, i.e. a simple mask of word "opera" suffices:
----------------------------
2021-03-09 22:19:25.424813: PT match, uid: 1000, exe: /snap/opera/113/usr/lib/x86_64-linux-gnu/opera/opera, cmdl: n/a
2021-03-09 22:19:25.425522: PT stats, users: 1, cache: 245, add: 19, rm: 1, lost: 0, nocmd: 0, qc: 2, changed: 0, admatch: 19
----------------------------

Please check once more, maybe there was a little typo in your mask previously, like an unwanted space somewhere or so.

[Authmane Terki (authmaneterki)]

Hello,

For the permission error, it's because I do that:
chattr +i /var/lib/timekpr/config/timekpr.authmane512.conf

I do that to dissuade me from changing time limits in the config. If I really need to change the config, I simply do that:
chattr -i /var/lib/timekpr/config/timekpr.authmane512.conf

Is it really a problem if I don't change the config between these 2 commands?

I tried again timekpr without regexp for opera, freetube and dolphin-emu and you're right, now it seems to work. I think that your last update solved both the problems. :-D But I'm going to continue checking that like 1 week and then I'll confirm if the problem is definitely solved.

Thank you!

[Eduards Bezverhijs (mjasnik)]

Config files have to be writable unless the file itself is correct. If file is not correct, timekpr will try to fix it and if file is not writable, problems arise :)
Obviously, any changes in administration application will require the file to be writable too.

If changes in config are done using GUI or CLI tools, you can deny writing to it right away, but if done manually in config file, I would suggest you wait one minute and only then deny writes to the file. This is due to 30 sec (default) reload interval if the file is modified externally.

To be precise, update solved only snap/flatpak process termination issue, there was nothing else ;)