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.

Sign up for GitHub

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

Jump to bottom

[BUG] service.libreelec.settings: crash kodi on shutdown/reboot #5645

Closed
ysard opened this issue Sep 16, 2021 · 5 comments
Closed

[BUG] service.libreelec.settings: crash kodi on shutdown/reboot #5645

ysard opened this issue Sep 16, 2021 · 5 comments
Labels
BUGFIX WORK IN PROGRESS

Comments

@ysard
Copy link

ysard commented Sep 16, 2021

Describe the bug

Hello, I am currently modifying the addon service.libreelec.settings to adapt it to a Kodi installation on Debian 10 in order to benefit from the good support of bluetooth via this addon without reinventing the wheel myself. This is a personal use for the moment.
I am facing a long time bug causing a crash/segfault of kodi in case of reboot or shutdown of the system initiated from the interface.

Similar problems seem to be solved in the past by several commits (non exhaustive list) and linked to the use of D-Bus:
xbmc/xbmc#17718
https://forum.kodi.tv/showthread.php?tid=343069&pid=2934136#pid2934136

This problem is exclusively due to the addon because it does not occur in its absence.

To Reproduce

The message "## LibreELEC Addon ## STOP SERVICE DONE !" appears in the kodi log which does not display any error.
The oe.stop_service() method is therefore correctly executed:
https://github.com/LibreELEC/service.libreelec.settings/blob/8b1efa30632dd4b5c0493cfab2cc940a927392de/service.py#L104

Steps to avoid the crash:

Since the following service stop code is trivial (end of Monitor.run() method) and unlikely to be involved, I decided to explicitly remove the global variables created in dbus_utils.py

https://github.com/LibreELEC/service.libreelec.settings/blob/master/resources/lib/dbus_utils.py#L118-L122

Lines added at the end of:
https://github.com/LibreELEC/service.libreelec.settings/blob/8b1efa30632dd4b5c0493cfab2cc940a927392de/service.py#L78

# module header
import gc
gc.set_debug(gc.DEBUG_LEAK)

...
# end of Monitor.run()
del service_thread
del dbus_utils.LOOP_THREAD
del dbus_utils.LOOP
del dbus_utils.BUS

n = gc.collect()
xbmc.log("Unreachable objects: " + str(n))
xbmc.log("Remaining Garbage: " + str(len(gc.garbage)))

Only del dbus_utils.BUS followed by a collection seems really useful.

Here is the log:

## LibreELEC Addon ## STOP SERVICE DONE !
ERROR <general>: Exception ignored in:
ERROR <general>: <function Connection.__del__ at 0x7f233eb88488>
ERROR <general>:

ERROR <general>: Traceback (most recent call last):
ERROR <general>:   File "/home/pi/.local/lib/python3.7/site-packages/ravel.py", line 287, in __del__
ERROR <general>:
ERROR <general>: remove_listeners(self._client_dispatch, [])
ERROR <general>:
ERROR <general>:   File "/home/pi/.local/lib/python3.7/site-packages/ravel.py", line 268, in remove_listeners
ERROR <general>:
ERROR <general>: for interface in level.interfaces.values() :
ERROR <general>:
ERROR <general>: AttributeError
ERROR <general>: :
ERROR <general>: '_ClientDispatchNode' object has no attribute 'interfaces'

DEBUG <general>: Unreachable objects: 310
DEBUG <general>: Remaining Garbage: 0

The dbus connection object does not seem to be deleted correctly, even if it is explicitly requested with del.
The _ClientDispatchNode object in does not indeed contain an interfaces attribute, but I don't know enough about the dbussy package and its ravel module to say.
Besides, the documentation is sometimes minimal...

The problem seems to be due to a failure to clean the variables for a reason that I can not figure out.
I hope that this will put you on the track of a definitive resolution of the problem related to the management of dbus.

Informations

  • LE Version: _
  • Hardware Platform: _
  • LE settings:
    Taken from Testing LibreELEC-settings addon #4547
    service.libreelec.settings-10.0-20210809.zip
  • dbussy version: 1.3 (from pypi)
  • Python: 3.7 (debian buster)

Additional notes

I also found a typo in this code:

https://github.com/LibreELEC/service.libreelec.settings/blob/8b1efa30632dd4b5c0493cfab2cc940a927392de/resources/lib/dbus_utils.py#L85-L87

https://github.com/LibreELEC/service.libreelec.settings/blob/8b1efa30632dd4b5c0493cfab2cc940a927392de/resources/lib/dbus_utils.py#L49-L55

This is the worst way to cast a boolean to a string in Python, the syntax should be simply:
str(int(data))
ysard added a commit to ysard/service.libreelec.settings that referenced this issue Nov 4, 2021
@ysard
Fix crash on shutdown LibreELEC/LibreELEC.tv#5645
7bfbcd3
This was referenced Nov 4, 2021
Open
Open
@heitbaum
Copy link
Contributor

heitbaum commented Nov 9, 2021

Linked WIP fix: LibreELEC/service.libreelec.settings#245

@ysard
Copy link
Author

ysard commented Nov 11, 2021

I'm adding some more recent logs.

Shutdown Kodi with del on BUS variable

2021-11-09 18:59:14.561 T:878     DEBUG <general>: ## LibreELEC Addon ## STOP SERVICE DONE !
2021-11-09 18:59:14.562 T:878     DEBUG <general>: SETTINGS: Service_Thread.stop -
2021-11-09 18:59:14.562 T:878     DEBUG <general>: SETTINGS: Service_Thread.stop < <Service_Thread(Thread-2, started daemon 140271913600768)>
2021-11-09 18:59:14.562 T:912      INFO <general>: SETTINGS: run # Received exit
2021-11-09 18:59:14.562 T:912     DEBUG <general>: SETTINGS: Service_Thread.run > None
2021-11-09 18:59:14.562 T:878     DEBUG <general>: SETTINGS: Service_Thread.stop > None
2021-11-09 18:59:14.562 T:878     DEBUG <general>: SETTINGS: LoopThread.stop -
2021-11-09 18:59:14.562 T:878     DEBUG <general>: SETTINGS: LoopThread.stop < <LoopThread(Thread-1, started 140271925925632)>
2021-11-09 18:59:14.754 T:907     DEBUG <general>: SETTINGS: LoopThread.run > None
2021-11-09 18:59:14.754 T:878     DEBUG <general>: SETTINGS: LoopThread.stop > None
2021-11-09 18:59:14.785 T:878     DEBUG <general>: SETTINGS: Monitor.run > None
2021-11-09 18:59:14.785 T:878      INFO <general>: CPythonInvoker(2, /home/pi/.kodi/addons/service.libreelec.settings/service.py): script successfully run
2021-11-09 18:59:14.786 T:878     DEBUG <general>: onExecutionDone(2, /home/pi/.kodi/addons/service.libreelec.settings/service.py)
2021-11-09 18:59:14.786 T:878     DEBUG <general>: .
2021-11-09 18:59:14.805 T:878      INFO <general>: Python interpreter interrupted by user
2021-11-09 18:59:14.805 T:804     DEBUG <general>: CPythonInvoker(2, /home/pi/.kodi/addons/service.libreelec.settings/service.py): script termination took 250ms
2021-11-09 18:59:14.806 T:804     DEBUG <general>: CServiceAddonManager: stopping service.xbmc.versioncheck.
2021-11-09 18:59:14.806 T:878     DEBUG <general>: Thread LanguageInvoker 140272801400576 terminating
2021-11-09 18:59:14.806 T:804      INFO <general>: CServiceAddonManager: failed to stop service.xbmc.versioncheck (may have ended)
2021-11-09 18:59:14.806 T:851     DEBUG <general>: Thread ActiveAE 140274460374784 terminating
2021-11-09 18:59:14.818 T:852     DEBUG <general>: Thread AESink 140274451982080 terminating
2021-11-09 18:59:15.043 T:808     DEBUG <general>: Sink changed
2021-11-09 18:59:15.044 T:804      INFO <general>: Application stopped
2021-11-09 18:59:15.254 T:804     DEBUG <general>: LogindUPowerSyscall - inhibit lock taken, fd 4
2021-11-09 18:59:15.324 T:804     DEBUG <general>: ------ Window Init (DialogBusy.xml) ------
2021-11-09 18:59:15.324 T:804      INFO <general>: XBApplicationEx: destroying...
2021-11-09 18:59:15.325 T:873     DEBUG <general>: Thread PeripEventScan 140273241093888 terminating
2021-11-09 18:59:15.340 T:867     DEBUG <general>: Thread PeripBusUSBUdev 140273266272000 terminating
2021-11-09 18:59:15.341 T:868     DEBUG <general>: Thread PeripBusCEC 140273257879296 terminating
2021-11-09 18:59:15.341 T:869     DEBUG <general>: Thread PeripBusAddon 140273249486592 terminating
2021-11-09 18:59:15.559 T:804      INFO <general>: unload skin
2021-11-09 18:59:15.561 T:804     DEBUG <general>: ------ Window Deinit (DialogButtonMenu.xml) ------
2021-11-09 18:59:15.561 T:804     DEBUG <general>: ------ Window Deinit (Home.xml) ------
2021-11-09 18:59:15.561 T:804     DEBUG <general>: FreeVisualisation() done
2021-11-09 18:59:15.568 T:804     DEBUG <general>: Skipped 1 duplicate messages..
2021-11-09 18:59:15.568 T:804     DEBUG <general>: ------ Window Deinit (DialogBusy.xml) ------
2021-11-09 18:59:15.571 T:804     DEBUG <general>: CloseBundle - Closed bundle
2021-11-09 18:59:15.576 T:804      INFO <general>: Unloaded skin
2021-11-09 18:59:15.578 T:804      INFO <general>: unload sections
2021-11-09 18:59:15.580 T:804     DEBUG <general>: LogindUPowerSyscall - delay lock sleep released
2021-11-09 18:59:15.580 T:804     DEBUG <general>: LogindUPowerSyscall - delay lock shutdown released
2021-11-09 18:59:15.582 T:874     DEBUG <general>: Thread Timer 140272826578688 terminating
2021-11-09 18:59:15.583 T:809     DEBUG <general>: Thread Lirc 140274468767488 terminating
2021-11-09 18:59:15.584 T:804     DEBUG <general>: object 0 --> 0 instances
2021-11-09 18:59:15.584 T:804     DEBUG <general>: object 1 --> 0 instances
2021-11-09 18:59:15.584 T:804     DEBUG <general>: object 2 --> 0 instances
2021-11-09 18:59:15.584 T:804     DEBUG <general>: object 3 --> 0 instances
2021-11-09 18:59:15.584 T:804     DEBUG <general>: object 4 --> 0 instances
2021-11-09 18:59:15.584 T:804     DEBUG <general>: object 5 --> 0 instances
2021-11-09 18:59:15.584 T:804     DEBUG <general>: object 6 --> 0 instances
2021-11-09 18:59:15.584 T:804     DEBUG <general>: object 7 --> 0 instances
2021-11-09 18:59:15.584 T:804     DEBUG <general>: object 8 --> 0 instances
2021-11-09 18:59:15.584 T:804     DEBUG <general>: object 9 --> 0 instances
2021-11-09 18:59:15.587 T:804      INFO <general>: XRANDR: /usr/lib/x86_64-linux-gnu/kodi/kodi-xrandr --screen 0 --output HDMI-1 --mode 0x81

Shutdown Kodi without del on BUS variable

2021-11-09 18:45:05.503 T:3046    DEBUG <general>: ## LibreELEC Addon ## STOP SERVICE DONE !
2021-11-09 18:45:05.503 T:3046    DEBUG <general>: SETTINGS: Service_Thread.stop -
2021-11-09 18:45:05.503 T:3046    DEBUG <general>: SETTINGS: Service_Thread.stop < <Service_Thread(Thread-2, started daemon 139997634230016)>
2021-11-09 18:45:05.503 T:3059     INFO <general>: SETTINGS: run # Received exit
2021-11-09 18:45:05.503 T:3059    DEBUG <general>: SETTINGS: Service_Thread.run > None
2021-11-09 18:45:05.503 T:3046    DEBUG <general>: SETTINGS: Service_Thread.stop > None
2021-11-09 18:45:05.503 T:3046    DEBUG <general>: SETTINGS: LoopThread.stop -
2021-11-09 18:45:05.503 T:3046    DEBUG <general>: SETTINGS: LoopThread.stop < <LoopThread(Thread-1, started 139997647357696)>
2021-11-09 18:45:06.053 T:3055    DEBUG <general>: SETTINGS: LoopThread.run > None
2021-11-09 18:45:06.054 T:3046    DEBUG <general>: SETTINGS: LoopThread.stop > None
2021-11-09 18:45:06.054 T:3046    DEBUG <general>: SETTINGS: Monitor.run > None
2021-11-09 18:45:06.054 T:3046     INFO <general>: CPythonInvoker(2, /home/pi/.kodi/addons/service.libreelec.settings/service.py): script successfully run
2021-11-09 18:45:06.054 T:3046    DEBUG <general>: onExecutionDone(2, /home/pi/.kodi/addons/service.libreelec.settings/service.py)
2021-11-09 18:45:06.054 T:3046    DEBUG <general>: .
2021-11-09 18:45:06.083 T:3046     INFO <general>: Python interpreter interrupted by user
2021-11-09 18:45:06.083 T:3022    DEBUG <general>: CPythonInvoker(2, /home/pi/.kodi/addons/service.libreelec.settings/service.py): script termination took 585ms
2021-11-09 18:45:06.083 T:3022    DEBUG <general>: CServiceAddonManager: stopping service.xbmc.versioncheck.
2021-11-09 18:45:06.083 T:3046    DEBUG <general>: Thread LanguageInvoker 139998527211264 terminating
2021-11-09 18:45:06.083 T:3022     INFO <general>: CServiceAddonManager: failed to stop service.xbmc.versioncheck (may have ended)
2021-11-09 18:45:06.083 T:3027    DEBUG <general>: Thread ActiveAE 140000183580416 terminating
2021-11-09 18:45:06.117 T:3028    DEBUG <general>: Thread AESink 140000175187712 terminating
2021-11-09 18:45:06.313 T:3025    DEBUG <general>: Sink changed
2021-11-09 18:45:06.314 T:3022     INFO <general>: Application stopped

=> nothing more, the app crashed

@mglae
Copy link
Contributor

mglae commented Nov 11, 2021

I've removed LE 10 and 11 labels. This is reported for debian buster with Python: 3.7 (and likely without our asyncio patch).

IMO there is no report for LE.

Feedback is always welcome and we should test the resulting dbussy fix better sooner than later in nightlies.

@heitbaum
Copy link
Contributor

Is this still an issue?

@heitbaum
Copy link
Contributor

heitbaum commented Sep 6, 2023

Assuming that this is no longer a problem. If still an issue - please update and reopen the issue.

@heitbaum heitbaum closed this as completed Sep 6, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
BUGFIX WORK IN PROGRESS
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@heitbaum @mglae @ysard