Bug 237508 - net/minidlna 1.2.1 - minidlna stops sending SSDP notifies after a few hours
Summary: net/minidlna 1.2.1 - minidlna stops sending SSDP notifies after a few hours
Status: Closed FIXED
Alias: None
Product: Ports & Packages
Classification: Unclassified
Component: Individual Port(s) (show other bugs)
Version: Latest
Hardware: Any Any
: --- Affects Only Me
Assignee: Gleb Smirnoff
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-04-23 20:35 UTC by oliver
Modified: 2019-05-08 21:42 UTC (History)
1 user (show)

See Also:
bugzilla: maintainer-feedback? (glebius)


Attachments
minidlna log file (640.68 KB, text/plain)
2019-04-23 20:35 UTC, oliver
no flags Details
make timeout management in minidlna more robust (5.84 KB, patch)
2019-04-30 21:38 UTC, Gleb Smirnoff
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description oliver 2019-04-23 20:35:28 UTC
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
Comment 1 Gleb Smirnoff freebsd_committer 2019-04-23 20:42:18 UTC
Can you please confirm that you are running 1.2.1_4 version, not 1.2.1_3?
Comment 2 Gleb Smirnoff freebsd_committer 2019-04-23 21:24:40 UTC
Also, can you please show your network configuration, e.g. output of ifconfig.
Comment 3 oliver 2019-04-26 06:08:57 UTC
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
Comment 4 Gleb Smirnoff freebsd_committer 2019-04-26 15:58:37 UTC
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.
Comment 5 oliver 2019-04-28 15:29:33 UTC
======================================================================
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...
Comment 6 Gleb Smirnoff freebsd_committer 2019-04-30 20:31:32 UTC
> [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.
Comment 7 Gleb Smirnoff freebsd_committer 2019-04-30 21:38:01 UTC
Created attachment 204127 [details]
make timeout management in minidlna more robust
Comment 8 Gleb Smirnoff freebsd_committer 2019-04-30 21:38:21 UTC
Can you please test attached patch?
Comment 9 oliver 2019-05-01 11:23:08 UTC
(In reply to Gleb Smirnoff from comment #8)
I'm on my way...
Comment 10 oliver 2019-05-01 20:45:56 UTC
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.
Comment 11 Gleb Smirnoff freebsd_committer 2019-05-01 21:20:52 UTC
I'm also running with the patch. If it works well for both of us for couple days, I will update port.
Comment 12 oliver 2019-05-05 10:46:39 UTC
Minidlna is still sending SSDP notifies after three/four days of continuous running.
Comment 13 commit-hook freebsd_committer 2019-05-08 21:41:26 UTC
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