Not shutting down on SIGTERM

[wesx]

I recently experienced huge delays when shutting down. This comes from systemd sending an SIGTERM to the process dleyna-renderer-service and waiting for the service to actually stop.
Because of the service not shutting down systemd waits a 1min and 58secs before killing the service.
The only package that uses dleyna-renderer on my system was gnome-photos. Cause i never uses this i decided to temporarily uninstall gnome-photos and dleyna-renderer to reduce my shutdown time.

With the service still running i tried to send SIGTERM to it, but nothing happens, so it seems to be an problem with the service. If you give me the location of the logfiles i can paste them here.

My version of dleyna-renderer was 0.5.0-1 and im using Arch Linux.

I hope you can fix this, else it would be very annoying to use on systemd managed systems.

[szelek]

The problem still exists in version 0.6.0, also on Arch Linux.
I don't know if it's dleyna-renderer or Arch's package issue.

Below shutdown logs:
systemd[11373]: dbus.service: Killing process 12436 (dleyna-renderer) with signal SIGKILL. systemd[11373]: dbus.service: Failed with result 'timeout'.

[robhancock]

I have been seeing the same issue. Doing a pstack on the process shows a thread that seems to be stuck in this stack trace:

#0  0x00007f5bc55b4b99 in syscall () at /lib64/libc.so.6
#1  0x00007f5bc5e7450f in g_cond_wait () at /lib64/libglib-2.0.so.0
#2  0x00007f5bc6766a8f in soup_session_process_queue_item () at /lib64/libsoup-2.4.so.1
#3  0x00007f5bc676744e in soup_session_real_send_message () at /lib64/libsoup-2.4.so.1
#4  0x00007f5bc6e45d6e in gupnp_service_info_get_introspection () at /lib64/libgupnp-1.0.so.4
#5  0x00007f5bc768b761 in prv_props_update.isra () at /usr/lib64/dleyna-renderer/libdleyna-renderer-1.0.so.1
#6  0x00007f5bc768d01d in dlr_device_get_all_props () at /usr/lib64/dleyna-renderer/libdleyna-renderer-1.0.so.1
#7  0x00007f5bc747da8f in prv_process_task () at /lib64/libdleyna-core-1.0.so.4
#8  0x00007f5bc5e2b577 in g_idle_dispatch () at /lib64/libglib-2.0.so.0
#9  0x00007f5bc5e2eb77 in g_main_context_dispatch () at /lib64/libglib-2.0.so.0
#10 0x00007f5bc5e2ef20 in g_main_context_iterate.isra () at /lib64/libglib-2.0.so.0
#11 0x00007f5bc5e2f232 in g_main_loop_run () at /lib64/libglib-2.0.so.0
#12 0x00007f5bc747cbdc in dleyna_main_loop_start () at /lib64/libdleyna-core-1.0.so.4
#13 0x00007f5bc54e5f2a in __libc_start_main () at /lib64/libc.so.6
#14 0x000055ef9e8b39ba in _start ()

[phako]

That's supposed to be fixed by fixing #104

[fedelibre]

I confirm the problem on Fedora (here's the bug report).

[Madko]

Still there on Fedora 30 Beta

[rsbells]

If you are able to reproduce it. Can you try to resolve it and provide a patch?

[hifigraz]

Problem still exists V0.6.0

[hifigraz]

I'get a lot of core dumps. here is a backtrace:
[robert@Titan ~] $ gdb --core=core.27555 /usr/lib/dleyna-renderer-service
GNU gdb (GDB) 8.2.1
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later http://gnu.org/licenses/gpl.html
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-pc-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
http://www.gnu.org/software/gdb/bugs/.
Find the GDB manual and other documentation resources online at:
http://www.gnu.org/software/gdb/documentation/.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/lib/dleyna-renderer-service...(no debugging symbols found)...done.

warning: core file may not match specified executable file.
[New LWP 27555]
[New LWP 27558]
[New LWP 27557]
[New LWP 27560]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/usr/lib/libthread_db.so.1".
Core was generated by `/usr/lib/dleyna-renderer-service'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 0x00007f61f97ced70 in dlr_upnp_lost_client () from /usr/lib/dleyna-renderer/libdleyna-renderer-1.0.so.1
[Current thread is 1 (Thread 0x7f61f5c857c0 (LWP 27555))]
(gdb) bt
#0 0x00007f61f97ced70 in dlr_upnp_lost_client () at /usr/lib/dleyna-renderer/libdleyna-renderer-1.0.so.1
#1 0x00007f61f97cc4c4 in () at /usr/lib/dleyna-renderer/libdleyna-renderer-1.0.so.1
#2 0x00007f61f978a57d in () at /usr/lib/dleyna-1.0/connectors/libdleyna-connector-dbus.so
#3 0x00007f61f91d1a12 in () at /usr/lib/libgio-2.0.so.0
#4 0x00007f61f91d71b2 in () at /usr/lib/libgio-2.0.so.0
#5 0x00007f61f91de659 in () at /usr/lib/libgio-2.0.so.0
#6 0x00007f61f96a5661 in g_main_context_dispatch () at /usr/lib/libglib-2.0.so.0
#7 0x00007f61f96a7739 in () at /usr/lib/libglib-2.0.so.0
#8 0x00007f61f96a86d2 in g_main_loop_run () at /usr/lib/libglib-2.0.so.0
#9 0x00007f61f9763ab6 in dleyna_main_loop_start () at /usr/lib/libdleyna-core-1.0.so.5
#10 0x00007f61f9477ce3 in __libc_start_main () at /usr/lib/libc.so.6
#11 0x0000556ad96e209e in _start ()
(gdb)

[phako]

That's something completely different

[paulie4]

@rsbells, it happens at every shutdown, so yes, it's easily reproducible, but I'm not sure how to debug it. I edited my ~/.config/dleyna-renderer-service.conf to increase the log level and was going to restart the service, but even though I see the process running and started by systemd, I don't know how to control it with systemctl:

$ ps -O ppid -C dleyna-renderer
  PID  PPID S TTY          TIME COMMAND
 1553   878 S ?        00:00:00 /usr/lib/dleyna-renderer-service

$ ps -O ppid 878
  PID  PPID S TTY          TIME COMMAND
  878     1 S ?        00:00:00 /usr/lib/systemd/systemd --user

$ systemctl --user status dleyna-renderer-service
Unit dleyna-renderer-service.service could not be found.

$ systemctl --user status dleyna-renderer
Unit dleyna-renderer.service could not be found.

[davidstrauss]

@paulie4 At least on Fedora, it does not appear to run as a systemd service (either at the system level or, where you're looking with --user, the user session level). Fedora's packaging of dleyna-renderer ships the service configuration via /usr/share/dbus-1/services/com.intel.dleyna-renderer.service, which leverages the D-Bus Specification for services.

[paulie4]

@davidstrauss, I'm using Arch Linux. I do see that I have a /usr/share/dbus-1/services/com.intel.dleyna-renderer.service file, but as you can see from my ps output in my previous comment, the parent process of the /usr/lib/dleyna-renderer-service process is /usr/lib/systemd/systemd --user. I couldn't see an easy way to stop/start a service in the D-Bus spec you pointed to, so I just restarted my comp instead. How would you stop/start the service?

It doesn't seem like the log-level=8 change I made to dleyna-renderer-service.conf made a difference. This is what I see in my systemd journal (the only thing that changed between machine reboots was the log level from 0x13 to 0x3F):

...
May 12 16:12:17 scruffy dbus-daemon[884]: [session uid=1000 pid=884] Activating service name='com.intel.dleyna-renderer' requested by ':1.64' (uid=1000 pid=1423 comm="/usr/bin/gnome-photos --gapplication-service ")
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: dLeyna core version 0.6.0
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: dleyna-renderer-service version 0.6.0
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: Type[0] Level[0x3F] Mask[0x4C] Flags[0x4F]
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: Load file [/home/paulie/.config/dleyna-renderer-service.conf]
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: [General settings]
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: Never Quit: F
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: Connector Name: dbus
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: Port: 0
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: Push host port: 0
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: [Logging settings]
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: Log Type : 0
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: Log Level: 0x3F
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: [Network filtering settings]
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: Enabled : F
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: Entries: (null)
May 12 16:12:17 scruffy dbus-daemon[884]: [session uid=1000 pid=884] Successfully activated service 'com.intel.dleyna-renderer'
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: Calling GetRenderers method
May 12 16:12:17 scruffy dleyna-renderer-service[1520]: New media server /com/intel/dLeynaRenderer/server/uuid_3aRINCON_5CAAFD296F0001400_MR
...
May 12 16:19:03 scruffy systemd[860]: dbus.service: State 'stop-final-sigterm' timed out. Killing.
May 12 16:19:03 scruffy systemd[860]: dbus.service: Killing process 1520 (dleyna-renderer) with signal SIGKILL.
May 12 16:19:03 scruffy systemd[860]: dbus.service: Failed with result 'timeout'.
...

Should there have been a log message if/when the service got a message to shutdown, which would mean that it did not get a shutdown message?

[davidstrauss]

@paulie4 systemd is parent to a lot of things as a user session manager, but it doesn't necessarily mean that it manages the lifecycle of something directly. Based on your logs, it looks like that the only service systemd is aware of there is dbus.service, which I suspect is your entire user session D-Bus daemon (rather than host-level) as well as anything that D-Bus daemon is launching. In this case, your user D-Bus daemon appears to launch the dleyna-renderer-service as a D-Bus (but not directly systemd) service. If the dleyna-renderer-service is double forking, it may be intentionally detaching from the D-Bus parent PID and getting re-parented to systemd. However, since systemd uses cgroups to track PID-to-service affiliations (not parent PIDs), systemd still considers the dleyna-renderer-service PID part of dbus.service and expects it to exit when dbus.service shuts down.

At least one of the following should be happening to prevent this:

• dbus.service can be (and currently is) configured to have all contained PIDs sent a shutdown signal. In this model, services like dleyna-renderer-service should respond to the signal by exiting gracefully.
• Alternatively, dbus.service could be configured to only have the main D-Bus PID sent the shutdown signal by systemd. However, D-Bus would then be responsible for cleaning up any other PIDs it launched.
• Finally, dleyna-renderer-service could be configured to run as its own systemd service, not just launched within dbus.service. There would still need to be a way for dleyna-renderer-service to cleanly shut down, but it would isolate the problem from everything else in D-Bus.

How would you stop/start the service?

D-Bus seems to start it based on bus activity. I'm not a D-Bus expert, though. I'm just trying to explain why the service doesn't seem to appear directly in systemd's interfaces even though systemd has the parent PID. I do not know how to instruct a D-Bus-style service to shut down or even if there's a single convention for doing so.

Should there have been a log message if/when the service got a message to shutdown, which would mean that it did not get a shutdown message?

There would be logging of a similar sort if dleyna-renderer-service were directly a systemd service, but it is not. I'm unsure what to expect for a D-Bus service.

[paulie4]

Do you have any suggested next steps on what to do to debug what the problem could be? Thanks!