Created attachment 203944 [details] minidlna log file I upgraded my system to freebsd 12.0-Release. Minidlna was updated to 1.2.1 Minidlna stops sending SSDP notifies (and stops answering to SSDP M-SEARCH requests as well apparently) after a few hours. If you look into the log file (attached), today minidlna stopped sending notifies at 06:55. Needles to say the serveur is running 24/7. Minidlna started again sending notifies at 21:38 after a manual restart of the service. EXTRACT OF LOG (log file attached) [2019/04/23 06:53:11] minidlna.c:1226: debug: Sending SSDP notifies [2019/04/23 06:54:11] minidlna.c:1226: debug: Sending SSDP notifies [2019/04/23 06:55:11] minidlna.c:1226: debug: Sending SSDP notifies [2019/04/23 21:38:41] minidlna.c:1226: debug: Sending SSDP notifies [2019/04/23 21:39:41] minidlna.c:1226: debug: Sending SSDP notifies [2019/04/23 21:40:41] minidlna.c:1226: debug: Sending SSDP notifies Before restarting the service, I checked that minidlna was still listening on ports r1900 and 8200 and the status of the service. I report the bug as I had to restart the service several times since freebsd upgrade (two days ago) Note that my config files sepecifies: notify_interval=60 I will remove it right now, just in case.... if there is any improvment I'll report it (but it would be surprising) ============================================ Here follows my conf file stripped from comments: port=8200 network_interface=igb0 user=dlna media_dir=V,/daemonpool/daemonfs/video_u media_dir=V,/daemonpool/daemonfs/audio_u/CLIPS media_dir=A,/daemonpool/daemonfs/audio_u/musique/mp3-Olivier merge_media_dirs=no friendly_name=NAS db_dir=/var/db/minidlna log_dir=/var/log log_level=general,artwork,database,inotify,scanner,metadata,http=debug,ssdp=debug,tivo=warn album_art_names=Cover.jpg/cover.jpg/AlbumArtSmall.jpg/albumartsmall.jpg/AlbumArt.jpg/albumart.jpg/Album.jpg/album.jpg/Folder.jpg/folder.jpg/Thumb.jpg/thumb.jpg inotify=yes enable_tivo=no strict_dlna=no notify_interval=60 serial=12345678 model_number=1 root_container=B force_sort_criteria=+upnp:class,+upnp:originalTrackNumber,+dc:title max_connections=100
Can you please confirm that you are running 1.2.1_4 version, not 1.2.1_3?
Also, can you please show your network configuration, e.g. output of ifconfig.
Here follow the required information.... root@nas:~ # pkg info | grep minidlna minidlna-1.2.1_4,1 Media-server compatible with "Digital Life Network Alliance" root@nas:~ # ifconfig igb0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500 options=e507bb<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,TSO4,TSO6,LRO,VLAN_HWFILTER,VLAN_HWTSO,RXCSUM_IPV6,TXCSUM_IPV6> ether 00:25:90:f5:bb:1a inet 192.168.1.7 netmask 0xffffff00 broadcast 192.168.1.255 media: Ethernet autoselect (1000baseT <full-duplex>) status: active nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL> igb1: flags=8802<BROADCAST,SIMPLEX,MULTICAST> metric 0 mtu 1500 options=e507bb<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,TSO4,TSO6,LRO,VLAN_HWFILTER,VLAN_HWTSO,RXCSUM_IPV6,TXCSUM_IPV6> ether 00:25:90:f5:bb:1b media: Ethernet autoselect status: no carrier nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL> lo0: flags=8049<UP,LOOPBACK,RUNNING,MULTICAST> metric 0 mtu 16384 options=680003<RXCSUM,TXCSUM,LINKSTATE,RXCSUM_IPV6,TXCSUM_IPV6> inet6 ::1 prefixlen 128 inet6 fe80::1%lo0 prefixlen 64 scopeid 0x3 inet 127.0.0.1 netmask 0xff000000 groups: lo nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL> pflog0: flags=141<UP,RUNNING,PROMISC> metric 0 mtu 33160 groups: pflog
Can you please increase logging level and see if there is any messages when it stops working? If this doesn't give any clue, can you please attach to the process with gdb and trace it step by step? The main event loop is a small piece of code.
====================================================================== Here follows my new log level (from minidlna.conf): log_level=debug,artwork=debug,database=debug,inotify=debug,scanner=debug,metadata=debug,http=debug,ssdp=debug,tivo=debug ====================================================================== Here follows the log file. Strangely the log file ends when (I suppose) minidlna stops sending SSDP notifies. root@nas:~ # tail -n 50 /var/log/minidlna.log TIMEOUT: Second-300 SID: uuid:6cb92f7e-69b9-11e9-b168-002590f5bb1a CONNECTION: close [2019/04/28 15:31:38] upnphttp.c:750: debug: ProcessHTTPSubscribe /evt/ContentDir [2019/04/28 15:31:38] upnphttp.c:752: debug: Callback '' Timeout=300 [2019/04/28 15:31:38] upnphttp.c:753: debug: SID 'uuid:6cb92f7e-69b9-11e9-b168-002590f5bb1a' [2019/04/28 15:31:38] upnphttp.c:1229: debug: HTTP RESPONSE: HTTP/1.1 200 OK Content-Type: text/xml; charset="utf-8" Connection: close Content-Length: 0 Server: 12.0-RELEASE-p3 DLNADOC/1.50 UPnP/1.0 MiniDLNA/1.2.1 Timeout: Second-300 SID: uuid:6cb92f7e-69b9-11e9-b168-002590f5bb1a Date: Sun, 28 Apr 2019 13:31:38 GMT EXT: [2019/04/28 15:31:38] kqueue.c:199: debug: kevent timer: 13123, changes: 0 [2019/04/28 15:31:51] kqueue.c:209: debug: kevent events: 0 [2019/04/28 15:31:51] minidlna.c:1226: debug: Sending SSDP notifies [2019/04/28 15:31:51] kqueue.c:199: debug: kevent timer: 60000, changes: 0 [2019/04/28 15:32:42] kqueue.c:209: debug: kevent events: 1 [2019/04/28 15:32:42] minidlna.c:172: debug: HTTP connection from 192.168.1.6:3436 [2019/04/28 15:32:42] kqueue.c:111: debug: kqueue_add 854 [2019/04/28 15:32:42] kqueue.c:199: debug: kevent timer: 8399, changes: 1 [2019/04/28 15:32:42] kqueue.c:209: debug: kevent events: 1 [2019/04/28 15:32:42] clients.c:333: debug: Client found in cache. [Denon Receiver/entry 0] [2019/04/28 15:32:42] upnphttp.c:894: debug: HTTP REQUEST: UNSUBSCRIBE /evt/ContentDir HTTP/1.1 Host: 192.168.1.7:8200 SID: uuid:6cb92f7e-69b9-11e9-b168-002590f5bb1a CONNECTION: close [2019/04/28 15:32:42] upnphttp.c:802: debug: ProcessHTTPUnSubscribe /evt/ContentDir [2019/04/28 15:32:42] upnphttp.c:803: debug: SID 'uuid:6cb92f7e-69b9-11e9-b168-002590f5bb1a' [2019/04/28 15:32:42] upnpevents.c:192: debug: removeSubscriber(uuid:6cb92f7e-69b9-11e9-b168-002590f5bb1a) [2019/04/28 15:32:42] upnphttp.c:1229: debug: HTTP RESPONSE: HTTP/1.1 200 OK Content-Type: text/xml; charset="utf-8" Connection: close Content-Length: 0 Server: 12.0-RELEASE-p3 DLNADOC/1.50 UPnP/1.0 MiniDLNA/1.2.1 Date: Sun, 28 Apr 2019 13:32:42 GMT EXT: [2019/04/28 15:32:42] kqueue.c:199: debug: kevent timer: 8398, changes: 0 [2019/04/28 15:32:51] kqueue.c:209: debug: kevent events: 0 [2019/04/28 15:32:51] kqueue.c:199: debug: kevent timer: 0, changes: 0 ====================================================================== I attached the running minidlna process, but it doesn't show anything root@nas:~ # gdb attach 48511 GNU gdb (GDB) 8.2.1 [GDB v8.2.1 for FreeBSD] 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-portbld-freebsd12.0". 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"... attach: No such file or directory. Attaching to process 48511 Reading symbols from /usr/local/sbin/minidlnad...(no debugging symbols found)...done. .......... Stripped for readability ........ Reading symbols from /libexec/ld-elf.so.1...(no debugging symbols found)...done. [Switching to LWP 100111 of process 48511] 0x0000000800e6824a in _kevent () from /lib/libc.so.7 (gdb) continue Continuing. ============================================================================= And, the process is still running root@nas:~ # sockstat -4 -l USER COMMAND PID FD PROTO LOCAL ADDRESS FOREIGN ADDRESS root ntpd 13642 21 udp4 *:123 *:* root ntpd 13642 22 udp4 192.168.1.7:123 *:* root ntpd 13642 25 udp4 127.0.0.1:123 *:* dlna minidlnad 48511 851 udp4 *:1900 *:* dlna minidlnad 48511 852 tcp4 *:8200 *:* dlna minidlnad 48511 853 udp4 192.168.1.7:31929 *:* root sendmail 1120 3 tcp4 127.0.0.1:25 *:* root sshd 1117 3 tcp4 192.168.1.7:22 *:* root smbd 1069 36 tcp4 *:445 *:* root smbd 1069 37 tcp4 *:139 *:* root nmbd 1065 15 udp4 *:137 *:* root nmbd 1065 16 udp4 *:138 *:* root nmbd 1065 17 udp4 192.168.1.7:137 *:* root nmbd 1065 18 udp4 192.168.1.255:137 *:* root nmbd 1065 19 udp4 192.168.1.7:138 *:* root nmbd 1065 20 udp4 192.168.1.255:138 *:* root nfsd 918 5 tcp4 *:2049 *:* root mountd 916 9 udp4 *:686 *:* root mountd 916 10 tcp4 *:686 *:* root nfsuserd 894 3 udp4 *:755 *:* root nfsuserd 893 3 udp4 *:755 *:* root nfsuserd 892 3 udp4 *:755 *:* root nfsuserd 891 3 udp4 *:755 *:* root nfsuserd 890 3 udp4 *:755 *:* root rpcbind 862 9 udp4 *:111 *:* root rpcbind 862 10 udp4 *:650 *:* root rpcbind 862 11 tcp4 *:111 *:* root syslogd 840 7 udp4 *:514 *:* ? ? ? ? udp4 *:2049 *:* ============================================================================= To be 100% sure, I turned on my TV and it doesn't detect minidlna ============================================================================ I have a look at my log file, which is quite big. ls -al .... STRIPPED...... -rw-r--r-- 1 root wheel 85554555 Apr 28 15:33 minidlna.log ============================================================================ I'll remove that log file decrease all log levels and see how long the server stands up...
> [2019/04/28 15:32:51] kqueue.c:199: debug: kevent timer: 0, changes: 0 This clearly is a bug. Zero timer will make it sleep forever until a packet arrives, so periodic SSDP notify won't be sent. However, a packet from TV should wake up.
Created attachment 204127 [details] make timeout management in minidlna more robust
Can you please test attached patch?
(In reply to Gleb Smirnoff from comment #8) I'm on my way...
I'm presently testing the above mentionned patch... I'll keep you informed whether it works or not. > However, a packet from TV should wake up. My firewall drops these broadcast packets. I should change its config.
I'm also running with the patch. If it works well for both of us for couple days, I will update port.
Minidlna is still sending SSDP notifies after three/four days of continuous running.
A commit references this bug: Author: glebius Date: Wed May 8 21:40:46 UTC 2019 New revision: 501058 URL: https://svnweb.freebsd.org/changeset/ports/501058 Log: This update fixes bug when minidlna stops sending periodic SSDP notifies. PR: 237508 Changes: head/net/minidlna/Makefile head/net/minidlna/distinfo