Dnfdragora doesn't finish the job sometimes recently

[L-U-T-i]

I've noticed about a month ago that suddenly dnfdragora started to stuck at "running script" or "verifying" stage or so when updating selected packages (instead of cleaning the bottom bar and since 2.1.5 also displaying a window about the changes"). I've tried to leave it like that for hours, no change (I have to kill the window at the end...).

I believe the update process in such a case finishes successfully (no duplicate packages, no processes indicating something related to dnf or rpm is still running, no unfinished transactions or so...), it is just like dnfdragora hangs in some loop or so, waiting for something...

I've checked the updates in 2024. I've had a rebuild of dnfdaemon with a recent pull request, which actually doesn't change the code, just a .spec file I don't use anyway, and a dnfdragora update from 2.1.5 to 2.1.6 (which also shall not cause anything like that, evaluating the code change...).

I've also tried to revert both to the versions from 2023, which never manifested anything like that before. It still happens sometimes (not always, and I can't see a pattern about how to repeat it), so I suspect it has to do with the most recent change of dnf or python 3 or any other RedHat provided package (as I remember dnf has been updated in the beginning of 2024 at Rocky Linux 9.3).

@anaselli , do you have any idea about what could cause that or in which part of the code (if it is actually dnfdragora or dnfdaemon) to look to try to resolve it?

[anaselli]

Well probably dnfdragora did not receive (or manage) the end of transaction event for any reasons (a crash or failure). The only thing i can suggest is to enable logging and when happen share it so that we can understand what happened.

[L-U-T-i]

That is also my idea. But I don't know anything about how these events are passed (dnf to dnfdaemon and dnfdaemon to dnfdragora, or directly from dnf to dnfdragora?).

How can I do that? And, shall it be logging of dnfdragora or dnfdaemon or dnf?

[anaselli]

logging dnfdragora could be enough for starting. Set Log to debug level, it could be a little bit slower, but at least you can read all ether what it's doing or if there were any exceptions

[L-U-T-i]

Thank you. I haven't even noticed this option in Options -> User preferences... ;-)

Logging is enabled now, I have just updated a bunch of packages, without any problem. I will wait, and report back as soon as this bug kicks again.

BTW, I've noticed another interesting thing. I've enabled logging and debug (both checked), restarted dnfdragora but there was no log file. Tried to refresh metadata, nothing. Checked options are set, restarted dnfdragora again, still no log file in my home dir. Then I've created a subdirectory (within my home dir) and set this one in preferences. After restart, log file appeared immediately (in this new directory, of course), even before any activity selected. Now, the logging is working as expected (after rename of the log file, a new one was created as well). If I change the directory back to my home directory now, the log file is created there. It seems the problem is only the first time user selects logging, but doesn't do any directory selection.

[anaselli]

Will check it, maybe it doesn't work as expected with default settings. Certainly it does not write log if the directory isn't writable, honestly i can't remember if i checked that...

[L-U-T-i]

My home directory permissions were definitely not a problem, as log file has been written after I set directory (using the "Change directory" button) for the first time (changed from ~ to ~/dnfdragora, which I've created before, and back to ~after).

As said, I could change later from ~/dnfdragora back to ~, and log file was correctly written (now to ~ of course) as expected (so, no permission issue).

Probably some default directory setting (user's home directory) is missing (as long as user doesn't do a manual selection)?

[anaselli]

i didn't mean that, just that dnfdragora could use the default value wrongly... maybe with a directory that is not in your home... just gessing

[L-U-T-i]

I've checked (updatedb + locate dnfdragora.log) and there is no other dnfdragora.log as in ~/dnfdragora (I've deleted ~ one in between).

[L-U-T-i]

Just a feedback - since I've turned logging on, there was no such event anymore. Have no clue what might be, maybe some system package has been causing it...?

In any case, logging is still turned on on all 5 of my machines...

[anaselli]

well dnfdaemon could have disconnected for a long lasting call, or something in dnfdragora that with logging works better just because it is slower... let's see... By now i'm happy for you it works :)

[L-U-T-i]

I've caught it finally... ;-)

Here are the last lines, including the "interesting" part (before that, everything seems to be as expected):

2024-05-26 10:20:07,393 [dnfdragora.ui]{ui.py:1702}(DEBUG) OnRPMProgress: ('roundcubemail,0,1.5.7,1.el9,noarch,epel-testing', 'verify', 100, 100, 37, 40)
2024-05-26 10:20:07,393 [dnfdragora.ui]{ui.py:1712}(DEBUG) OnRPMProgress : [roundcubemail,0,1.5.7,1.el9,noarch,epel-testing]
2024-05-26 10:20:07,393 [dnfdragora.ui]{ui.py:1702}(DEBUG) OnRPMProgress: ('roundcubemail,0,1.5.6,1.el9,noarch,@System', 'verify', 100, 100, 38, 40)
2024-05-26 10:20:07,394 [dnfdragora.ui]{ui.py:1712}(DEBUG) OnRPMProgress : [roundcubemail,0,1.5.6,1.el9,noarch,@System]
2024-05-26 10:20:07,394 [dnfdragora.ui]{ui.py:1702}(DEBUG) OnRPMProgress: ('upx,0,4.2.4,1.el9,x86_64,epel-testing', 'verify', 100, 100, 39, 40)
2024-05-26 10:20:07,394 [dnfdragora.ui]{ui.py:1712}(DEBUG) OnRPMProgress : [upx,0,4.2.4,1.el9,x86_64,epel-testing]
2024-05-26 10:20:07,395 [dnfdragora.ui]{ui.py:1702}(DEBUG) OnRPMProgress: ('upx,0,4.2.3,1.el9,x86_64,@System', 'verify', 100, 100, 40, 40)
2024-05-26 10:20:07,395 [dnfdragora.ui]{ui.py:1712}(DEBUG) OnRPMProgress : [upx,0,4.2.3,1.el9,x86_64,@System]
2024-05-26 10:20:07,396 [dnfdaemon.client]{dnfd_client.py:270}(DEBUG) return_handler RunTransaction
2024-05-26 10:20:07,396 [dnfdaemon.client]{dnfd_client.py:292}(DEBUG) get_result RunTransaction
2024-05-26 10:20:07,396 [dnfdaemon.client]{dnfd_client.py:283}(DEBUG) Quit return_handler error g-io-error-quark: GDBus.Error:org.freedesktop.DBus.Python.TypeError: Traceback (most recent call last):
  File "/usr/lib64/python3.9/site-packages/dbus/service.py", line 715, in _message_cb
    retval = candidate_method(self, *args, **keywords)
  File "/usr/lib/python3.9/site-packages/dnfdaemon/server/__init__.py", line 68, in newFunc
    rc = func(*args, **kwargs)
  File "/usr/share/dnfdaemon/dnfdaemon-system", line 540, in RunTransaction
    result = self.run_transaction()
  File "/usr/lib/python3.9/site-packages/dnfdaemon/server/__init__.py", line 645, in run_transaction
    self.base.do_transaction(display=display)
  File "/usr/lib/python3.9/site-packages/dnf/base.py", line 1036, in do_transaction
    self._plugins.unload_removed_plugins(self.transaction)
  File "/usr/lib/python3.9/site-packages/dnf/plugin.py", line 184, in unload_removed_plugins
    plugins[inspect.getfile(plugin.__class__)] = plugin
  File "/usr/lib64/python3.9/inspect.py", line 666, in getfile
    raise TypeError('{!r} is a built-in class'.format(object))
TypeError: <class 'dnf.plugin.dynamic.debuginfo-install.DebuginfoInstall'> is a built-in class
 (36)
2024-05-26 10:20:07,597 [dnfdragora.ui]{ui.py:1946}(ERROR) Event received RunTransaction, g-io-error-quark: GDBus.Error:org.freedesktop.DBus.Python.TypeError: Traceback (most recent call last):
  File "/usr/lib64/python3.9/site-packages/dbus/service.py", line 715, in _message_cb
    retval = candidate_method(self, *args, **keywords)
  File "/usr/lib/python3.9/site-packages/dnfdaemon/server/__init__.py", line 68, in newFunc
    rc = func(*args, **kwargs)
  File "/usr/share/dnfdaemon/dnfdaemon-system", line 540, in RunTransaction
    result = self.run_transaction()
  File "/usr/lib/python3.9/site-packages/dnfdaemon/server/__init__.py", line 645, in run_transaction
    self.base.do_transaction(display=display)
  File "/usr/lib/python3.9/site-packages/dnf/base.py", line 1036, in do_transaction
    self._plugins.unload_removed_plugins(self.transaction)
  File "/usr/lib/python3.9/site-packages/dnf/plugin.py", line 184, in unload_removed_plugins
    plugins[inspect.getfile(plugin.__class__)] = plugin
  File "/usr/lib64/python3.9/inspect.py", line 666, in getfile
    raise TypeError('{!r} is a built-in class'.format(object))
TypeError: <class 'dnf.plugin.dynamic.debuginfo-install.DebuginfoInstall'> is a built-in class
 (36) - status DNFDragoraStatus.RUN_TRANSACTION
2024-05-26 11:01:10,001 [dnfdragora.dnf_backend]{dnf_backend.py:189}(INFO) Quit
2024-05-26 11:01:10,399 [dnfdragora.dnf_backend]{dnf_backend.py:192}(INFO) Unlock (True) Exit (False)
2024-05-26 11:01:10,399 [dnfdragora]{dnfdragora:116}(INFO) Closing dnfdragora

All packages were properly updated, just the display wasn't cleaned out, but seemd to remain like frozen.

Does it help anyhow?

[L-U-T-i]

Got another one (as another user, on the same machine):

2024-05-29 10:03:57,148 [dnfdragora.ui]{ui.py:240}(INFO) dnfdragora started
2024-05-29 10:03:57,265 [dnfdragora.ui]{ui.py:585}(INFO) System has createMenuBar, using menubar
2024-05-29 10:03:57,645 [dnfdragora.base]{basedragora.py:88}(WARNING) Get root backend. Locked (False)
2024-05-29 10:03:57,646 [dnfdragora.ui]{ui.py:1953}(INFO) Event Lock received (True)
2024-05-29 10:06:53,008 [dnfdragora.ui]{ui.py:1946}(ERROR) Event received RunTransaction, g-io-error-quark: GDBus.Error:org.freedesktop.DBus.Python.TypeError: Traceback (most recent call last):
  File "/usr/lib64/python3.9/site-packages/dbus/service.py", line 715, in _message_cb
    retval = candidate_method(self, *args, **keywords)
  File "/usr/lib/python3.9/site-packages/dnfdaemon/server/__init__.py", line 68, in newFunc
    rc = func(*args, **kwargs)
  File "/usr/share/dnfdaemon/dnfdaemon-system", line 540, in RunTransaction
    result = self.run_transaction()
  File "/usr/lib/python3.9/site-packages/dnfdaemon/server/__init__.py", line 645, in run_transaction
    self.base.do_transaction(display=display)
  File "/usr/lib/python3.9/site-packages/dnf/base.py", line 1036, in do_transaction
    self._plugins.unload_removed_plugins(self.transaction)
  File "/usr/lib/python3.9/site-packages/dnf/plugin.py", line 184, in unload_removed_plugins
    plugins[inspect.getfile(plugin.__class__)] = plugin
  File "/usr/lib64/python3.9/inspect.py", line 666, in getfile
    raise TypeError('{!r} is a built-in class'.format(object))
TypeError: <class 'dnf.plugin.dynamic.debuginfo-install.DebuginfoInstall'> is a built-in class
 (36) - status DNFDragoraStatus.RUN_TRANSACTION
2024-05-29 10:26:12,665 [dnfdragora.dnf_backend]{dnf_backend.py:189}(INFO) Quit
2024-05-29 10:26:13,132 [dnfdragora.dnf_backend]{dnf_backend.py:192}(INFO) Unlock (True) Exit (False)
2024-05-29 10:26:13,132 [dnfdragora]{dnfdragora:116}(INFO) Closing dnfdragora

The last 3 lines were added when I've clicked a "Quit" button (with a greyed out list of packages being updated still there, and some line below like an update is still in progress...) , after approx. 20 minutes of waiting.

[L-U-T-i]

Maybe this issue is related to this (dnfdaemon related): Failed loading plugin "debuginfo-install": module 'dnf' has no attribute 'cli' #520

I'm also trying to replace an error message with just a debug message:

diff /usr/lib/python3.9/site-packages/dnfdragora/ui.py- /usr/lib/python3.9/site-packages/dnfdragora/ui.py
1946c1946,1949
<                 logger.error("Event received %s, %s - status %s", event, info['error'], self._status)
---
>                 if ("org.freedesktop.DBus.Python.TypeError" in info['error']) :
>                   logger.debug("ERROR : Event received %s, %s - status %s", event, info['error'], self._status)
>                 else:
>                   logger.error("Event received %s, %s - status %s", event, info['error'], self._status)

to see if there will be any difference (if dnfdragora will hang as by now, or it will just log an error and continue...).

I haven't had this issue since I've fixed dnf-plugins-core as above (I've fixed it back in February already, but obviously came back with some update after...) and implemented this patch though. I'll wait and see if it pops up again.