search

jcorporation / myMPD

myMPD is a standalone and mobile friendly web mpd client with a tiny footprint and advanced features.
https://jcorporation.github.io/myMPD/
GNU General Public License v3.0
421 stars 66 forks source link

Segmentation fault at startup on Debian 10.10 amd64 with mympd 8.0 #524

Closed tsunulukai closed 3 years ago

tsunulukai commented 3 years ago

myMPD version: 8.0

Describe the bug

After updating from previous release, mympd encounter a segmentation fault at startup. Purging the folder /var/lib/mympd does not solve the issue.

Problem happens with the "official" mympd debian package as well as with a home-compiled debian package using the "./build.sh sbuild_build" command.

Expected behavior

No segmentation fault at startup

Server plattform (please complete the following information):

Debug logs (please attach if it can be usefull)

# uname -a
Linux mpd-server 4.19.0-16-amd64 #1 SMP Debian 4.19.181-1 (2021-03-19) x86_64 GNU/Linux

# cat /etc/debian_version
10.10

# mympd -h
Usage: mympd [OPTION]...
myMPD 8.0.0
[...]

# export MYMPD_LOGLEVEL=7
# mympd
20:21:56 NOTICE   mympd     Workdir: "/var/lib/mympd"
20:21:56 NOTICE   mympd     Config dir: "/var/lib/mympd/config"
20:21:56 NOTICE   mympd     Setting loglevel to CRITICAL
Segmentation fault

Configuration (please attach if it can be usefull) irrelevant as it happens with a the default mympd configuration

jcorporation commented 3 years ago

I can not reproduce your error. Can you build a debug version with ./build.sh memcheck and run it with catchsegv debug/mympd or with gdb and post the backtrace.

tsunulukai commented 3 years ago

I didn't want to "pollute" my linux host with compilation packages, so I changed the contrib/packagin/debian/rules as follows to obtain the same result as with the build.sh memcheck:

# cat contrib/packaging/debian/rules
#!/usr/bin/make -f
export DH_VERBOSE = 1

BUILDDIR = release

build-arch: build

build-indep: build

build:
        ./build.sh createassets
        #cd $(BUILDDIR); cmake -DCMAKE_INSTALL_PREFIX:PATH=/usr -DCMAKE_BUILD_TYPE=RELEASE ..
        MEMCHECK=TRUE
        cd $(BUILDDIR); cmake -DCMAKE_INSTALL_PREFIX:PATH=/usr -DCMAKE_BUILD_TYPE=DEBUG -DMEMCHECK="$MEMCHECK" \
        -DENABLE_SSL="$ENABLE_SSL" -DENABLE_LIBID3TAG="$ENABLE_LIBID3TAG" -DENABLE_FLAC="$ENABLE_FLAC" \
        -DENABLE_LUA="$ENABLE_LUA" -DCMAKE_EXPORT_COMPILE_COMMANDS=ON ..

        make -C $(BUILDDIR)

binary: binary-indep binary-arch

binary-indep:

binary-arch:
        cd $(BUILDDIR); make install DESTDIR=../debian/tmp
        mkdir -p debian/tmp/DEBIAN
        cp debian/postinst debian/tmp/DEBIAN
        cp debian/postrm debian/tmp/DEBIAN
        dpkg-gencontrol -pmympd
        dpkg --build debian/tmp ..

clean:
        rm -rf $(BUILDDIR)

.PHONY: binary binary-arch binary-indep clean

Hopefully I didn't miss anything else the "memcheck" flag shoud have enabled.

Here's the output with the resulting mympd executable :

1 - with the /var/lib/mympd folder content from the previous working mympd release:

# catchsegv mympd
21:43:30 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/utility.c:212: Workdir: "/var/lib/mympd"
21:43:30 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/utility.c:212: Config dir: "/var/lib/mympd/config"
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State http_host: 127.0.0.1
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State http_port: 800
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State ssl: false
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State ssl_port: 4443
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State custom_cert: false
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State scriptacl: +127.0.0.0/8
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State lualibs: all
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State loglevel: 2
21:43:30 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/log.c:36: Setting loglevel to DEBUG
21:43:30 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:354: Starting myMPD 8.0.0
21:43:30 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:357: Libmympdclient 1.0.6 based on libmpdclient 2.20.0
21:43:30 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:358: Mongoose 7.3
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/web_server.c:74: Setting dns server to udp://192.168.1.1:53
2021-07-16 21:43:30  I mongoose.c:2733:mg_listen 1 accepting on http://127.0.0.1:800
21:43:30 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/web_server.c:96: Listening on http://127.0.0.1:800
21:43:30 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:92: Droping privileges to mympd
21:43:30 ERROR    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/utility.c:230: Document root: "/build/mympd-eUoqoF/mympd-8.0.0/htdocs" does not exist
21:43:30 INFO     mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/web_server.c:490: HTTP connection 1 closed
2021-07-16 21:43:30  I mongoose.c:1975:mg_mgr_fr All connections closed
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:438: Expiring web_server_queue: 0
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:441: Expired 0 entries
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:443: Expiring mympd_api_queue: 0
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:446: Expired 0 entries
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:448: Expiring mympd_script_queue: 0
21:43:30 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:451: Expired 0 entries

=================================================================
==15023==ERROR: LeakSanitizer: detected memory leaks

Direct leak of 16384 byte(s) in 1 object(s) allocated from:
    #0 0x556f708f9e00 in __interceptor_malloc (/usr/bin/mympd+0x364e00)
    #1 0x7fe299c4f1fc in install_handler ../debug/segfault.c:158

SUMMARY: AddressSanitizer: 16384 byte(s) leaked in 1 allocation(s).

2 - with a fresh /var/lib/mympd folder The HTTP & HTTPS ports have been changed because I have other services already listening on the default ports.

# catchsegv mympd
21:51:06 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/utility.c:212: Workdir: "/var/lib/mympd"
21:51:06 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/utility.c:212: Config dir: "/var/lib/mympd/config"
21:51:06 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State http_host: 0.0.0.0
21:51:06 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State http_port: 800

21:51:06 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State ssl: true
21:51:06 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State ssl_port: 4443

21:51:06 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State custom_cert: false
21:51:06 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State scriptacl: +127.0.0.0/8
21:51:06 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State lualibs: all
21:51:06 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/state_files.c:70: State loglevel: 5
21:51:06 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/log.c:36: Setting loglevel to DEBUG
21:51:06 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:354: Starting myMPD 8.0.0
21:51:06 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:357: Libmympdclient 1.0.6 based on libmpdclient 2.20.0
21:51:06 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:358: Mongoose 7.3
21:51:06 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/web_server.c:74: Setting dns server to udp://192.168.1.1:53
2021-07-16 21:51:06  I mongoose.c:2733:mg_listen 1 accepting on http://0.0.0.0:800
21:51:06 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/web_server.c:96: Listening on http://0.0.0.0:800
2021-07-16 21:51:06  I mongoose.c:2733:mg_listen 2 accepting on https://0.0.0.0:4443
21:51:06 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/web_server.c:109: Listening on https://0.0.0.0:4443
21:51:06 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:92: Droping privileges to mympd
21:51:06 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/utility.c:225: SSL cert dir: "/var/lib/mympd/ssl" created
21:51:06 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/cert.c:177: Creating self signed ca certificate
21:51:09 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/cert.c:195: Creating server certificate
21:51:09 NOTICE   mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/cert.c:210: Set server certificate san to: DNS:localhost, IP:127.0.0.1, IP:::1, DNS:mpd-server, DNS:mpd-server.lan, IP:192.168.1.2
21:51:09 ERROR    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/utility.c:230: Document root: "/build/mympd-eUoqoF/mympd-8.0.0/htdocs" does not exist
21:51:09 INFO     mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/web_server.c:490: HTTP connection 2 closed
21:51:09 INFO     mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/web_server.c:546: Connection 1 closed
2021-07-16 21:51:09  I mongoose.c:1975:mg_mgr_fr All connections closed
21:51:09 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:438: Expiring web_server_queue: 0
21:51:09 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:441: Expired 0 entries
21:51:09 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:443: Expiring mympd_api_queue: 0
21:51:09 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:446: Expired 0 entries
21:51:09 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:448: Expiring mympd_script_queue: 0
21:51:09 DEBUG    mympd     /build/mympd-eUoqoF/mympd-8.0.0/src/main.c:451: Expired 0 entries

=================================================================
==21568==ERROR: LeakSanitizer: detected memory leaks

Direct leak of 16384 byte(s) in 1 object(s) allocated from:
    #0 0x557580dc5e00 in __interceptor_malloc (/usr/bin/mympd+0x364e00)
    #1 0x7f1f088e01fc in install_handler ../debug/segfault.c:158

SUMMARY: AddressSanitizer: 16384 byte(s) leaked in 1 allocation(s).
jcorporation commented 3 years ago

In this logs myMPD exits because he can not access the htdocs directory. This is in most cases a permission problem. The segfault must occur later.

tsunulukai commented 3 years ago

That's strange. because it makes no difference running the package as root or as the mympd user. Moreover, I checked the permissions on /var/lib/mympd, and the mympd users has complete rwX access to it.

Is the htdoc folder content written on disk at runtime ? I don't see the htdoc folder in the debian packages: not in the one you provide in your release (https://download.opensuse.org/repositories/home:/jcorporation/Debian_10/amd64/mympd_8.0.0-1_amd64.deb), nor in the ones that get compiled with the build.sh sbuild_build command.

Now obviously, the path "/build/mympd-eUoqoF/mympd-8.0.0/htdocs" does not exist, as it is the temporary path those files were in during the package compiling process.

I spun up a blanco VM to compile directly without using sbuild.

I first installed the package from you repo using dpkg -i mympd_8.0.0-1_amd64.deb, then I built the package to get the debug build.

When I compile the package directly as root:

root@debianbuster:~# apt-get install cmake perl libssl-dev libid3tag0-dev libflac-dev liblua5.3-dev libpcre3-dev
root@debianbuster:~# git clone https://github.com/jcorporation/myMPD
root@debianbuster:~# cd myMPD/
root@debianbuster:~/myMPD# ./build.sh memcheck
[...]
make[2]: Leaving directory '/root/myMPD/debug'
[100%] Built target mympd-script
make[1]: Leaving directory '/root/myMPD/debug'
/usr/bin/cmake -E cmake_progress_start /root/myMPD/debug/CMakeFiles 0
Linking compilation database

root@debianbuster:~/myMPD# catchsegv debug/mympd
11:41:17 NOTICE   mympd     /root/myMPD/src/utility.c:212: Workdir: "/var/lib/mympd"
11:41:17 NOTICE   mympd     /root/myMPD/src/utility.c:225: Config dir: "/var/lib/mympd/config" created
11:41:17 NOTICE   mympd     /root/myMPD/src/log.c:36: Setting loglevel to DEBUG
11:41:17 NOTICE   mympd     /root/myMPD/src/main.c:354: Starting myMPD 8.0.0
11:41:17 NOTICE   mympd     /root/myMPD/src/main.c:357: Libmympdclient 1.0.6 based on libmpdclient 2.20.0
11:41:17 NOTICE   mympd     /root/myMPD/src/main.c:358: Mongoose 7.3
11:41:17 DEBUG    mympd     /root/myMPD/src/web_server.c:74: Setting dns server to udp://192.168.1.1:53
2021-07-17 09:41:17  I mongoose.c:2733:mg_listen 1 accepting on http://0.0.0.0:80
11:41:17 NOTICE   mympd     /root/myMPD/src/web_server.c:96: Listening on http://0.0.0.0:80
2021-07-17 09:41:17  I mongoose.c:2733:mg_listen 2 accepting on https://0.0.0.0:443
11:41:17 NOTICE   mympd     /root/myMPD/src/web_server.c:109: Listening on https://0.0.0.0:443
11:41:17 NOTICE   mympd     /root/myMPD/src/main.c:92: Droping privileges to mympd
11:41:17 NOTICE   mympd     /root/myMPD/src/utility.c:225: SSL cert dir: "/var/lib/mympd/ssl" created
11:41:17 NOTICE   mympd     /root/myMPD/src/cert.c:177: Creating self signed ca certificate
11:41:17 NOTICE   mympd     /root/myMPD/src/cert.c:195: Creating server certificate
11:41:17 NOTICE   mympd     /root/myMPD/src/cert.c:210: Set server certificate san to: DNS:localhost, IP:127.0.0.1, IP:::1, DNS:debianbuster, IP:127.0.1.1
11:41:17 ERROR    mympd     /root/myMPD/src/utility.c:230: Document root: "/root/myMPD/htdocs" does not exist
11:41:17 INFO     mympd     /root/myMPD/src/web_server.c:490: HTTP connection 2 closed
11:41:17 INFO     mympd     /root/myMPD/src/web_server.c:546: Connection 1 closed
2021-07-17 09:41:17  I mongoose.c:1975:mg_mgr_fr All connections closed
11:41:17 DEBUG    mympd     /root/myMPD/src/main.c:438: Expiring web_server_queue: 0
11:41:17 DEBUG    mympd     /root/myMPD/src/main.c:441: Expired 0 entries
11:41:17 DEBUG    mympd     /root/myMPD/src/main.c:443: Expiring mympd_api_queue: 0
11:41:17 DEBUG    mympd     /root/myMPD/src/main.c:446: Expired 0 entries
11:41:17 DEBUG    mympd     /root/myMPD/src/main.c:448: Expiring mympd_script_queue: 0
11:41:17 DEBUG    mympd     /root/myMPD/src/main.c:451: Expired 0 entries

So it seems mympd is trying to grab the htdocs folder from the location it was compiled.... Not sure this is a sane behavior :)

Now if I compile after cloning the repository in the /var/lib/mympd "home folder"

root@debianbuster:~# cd /var/lib/mympd/
root@debianbuster:/var/lib/mympd# git clone https://github.com/jcorporation/myMPD
root@debianbuster:/var/lib/mympd# cd myMPD/
root@debianbuster:/var/lib/mympd/myMPD# ./build.sh memcheck
[...]
make[2]: Leaving directory '/var/lib/mympd/myMPD/debug'
[100%] Built target mympd-script
make[1]: Leaving directory '/var/lib/mympd/myMPD/debug'
/usr/bin/cmake -E cmake_progress_start /var/lib/mympd/myMPD/debug/CMakeFiles 0
Linking compilation database

root@debianbuster:/var/lib/mympd/myMPD# catchsegv debug/mympd
11:55:14 NOTICE   mympd     /var/lib/mympd/myMPD/src/utility.c:212: Workdir: "/var/lib/mympd"
11:55:14 NOTICE   mympd     /var/lib/mympd/myMPD/src/utility.c:212: Config dir: "/var/lib/mympd/config"
11:55:14 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State http_host: 0.0.0.0
11:55:14 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State http_port: 80
11:55:14 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State ssl: true
11:55:14 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State ssl_port: 443
11:55:14 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State custom_cert: false
11:55:14 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State scriptacl: +127.0.0.0/8
11:55:14 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State lualibs: all
11:55:14 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State loglevel: 5
11:55:14 NOTICE   mympd     /var/lib/mympd/myMPD/src/log.c:36: Setting loglevel to DEBUG
11:55:14 NOTICE   mympd     /var/lib/mympd/myMPD/src/main.c:354: Starting myMPD 8.0.0
11:55:14 NOTICE   mympd     /var/lib/mympd/myMPD/src/main.c:357: Libmympdclient 1.0.6 based on libmpdclient 2.20.0
11:55:14 NOTICE   mympd     /var/lib/mympd/myMPD/src/main.c:358: Mongoose 7.3
11:55:14 DEBUG    mympd     /var/lib/mympd/myMPD/src/web_server.c:74: Setting dns server to udp://192.168.1.1:53
2021-07-17 09:55:14  I mongoose.c:2733:mg_listen 1 accepting on http://0.0.0.0:80
11:55:14 NOTICE   mympd     /var/lib/mympd/myMPD/src/web_server.c:96: Listening on http://0.0.0.0:80
2021-07-17 09:55:14  I mongoose.c:2733:mg_listen 2 accepting on https://0.0.0.0:443
11:55:14 NOTICE   mympd     /var/lib/mympd/myMPD/src/web_server.c:109: Listening on https://0.0.0.0:443
11:55:14 NOTICE   mympd     /var/lib/mympd/myMPD/src/main.c:92: Droping privileges to mympd
11:55:14 NOTICE   mympd     /var/lib/mympd/myMPD/src/utility.c:212: SSL cert dir: "/var/lib/mympd/ssl"
11:55:14 NOTICE   mympd     /var/lib/mympd/myMPD/src/cert.c:73: CA certificate and private key found
11:55:14 DEBUG    mympd     /var/lib/mympd/myMPD/src/cert.c:163: Certificate /var/lib/mympd/ssl/ca.pem expires in 3649 days
11:55:14 NOTICE   mympd     /var/lib/mympd/myMPD/src/cert.c:104: Server certificate and private key found
11:55:14 DEBUG    mympd     /var/lib/mympd/myMPD/src/cert.c:163: Certificate /var/lib/mympd/ssl/server.pem expires in 364 days
11:55:14 NOTICE   mympd     /var/lib/mympd/myMPD/src/utility.c:212: Document root: "/var/lib/mympd/myMPD/htdocs"
[...]

Now if I try this debug executable on my usual mpd server, after copying the htdocs directory in the expected spot: /var/lib/mympd/myMPD/htdocs

I get the following log:

# catchsegv debug/mympd
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/utility.c:212: Workdir: "/var/lib/mympd"
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/utility.c:212: Config dir: "/var/lib/mympd/config"
10:28:34 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State http_host: 127.0.0.1
10:28:34 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State http_port: 800
10:28:34 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State ssl: false
10:28:34 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State ssl_port: 4443
10:28:34 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State custom_cert: false
10:28:34 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State scriptacl: +127.0.0.0/8
10:28:34 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State lualibs: all
10:28:34 DEBUG    mympd     /var/lib/mympd/myMPD/src/state_files.c:70: State loglevel: 2
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/log.c:36: Setting loglevel to DEBUG
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/main.c:354: Starting myMPD 8.0.0
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/main.c:357: Libmympdclient 1.0.6 based on libmpdclient 2.20.0
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/main.c:358: Mongoose 7.3
10:28:34 DEBUG    mympd     /var/lib/mympd/myMPD/src/web_server.c:74: Setting dns server to udp://192.168.1.1:53
2021-07-17 10:28:34  I mongoose.c:2733:mg_listen 1 accepting on http://127.0.0.1:800
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/web_server.c:96: Listening on http://127.0.0.1:800
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/main.c:92: Droping privileges to mympd
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/utility.c:212: Document root: "/var/lib/mympd/myMPD/htdocs"
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/utility.c:212: State dir: "/var/lib/mympd/state"
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/utility.c:212: Smartpls dir: "/var/lib/mympd/smartpls"
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/utility.c:212: Pics dir: "/var/lib/mympd/pics"
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/utility.c:212: Empty dir: "/var/lib/mympd/empty"
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/utility.c:212: Scripts dir: "/var/lib/mympd/scripts"
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/utility.c:212: Covercache dir: "/var/lib/mympd/covercache"
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/main.c:401: Starting mympd api thread
10:28:34 NOTICE   mympd     /var/lib/mympd/myMPD/src/main.c:411: Starting webserver thread
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mympd_api/mympd_api_settings.c:408: Reading states
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State mpd_host: /run/mpd/socket
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State mpd_port: 6600
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State mpd_pass: nopassword
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State mpd_binarylimit: 4096
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State mpd_timeout: 10000
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State tag_list: Artist, Album, AlbumArtist, Title, Track, Genre, Date, Disc
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State tag_list_search: Artist, Album, AlbumArtist, Title, Genre
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State tag_list_browse: Artist, Album, AlbumArtist, Genre
10:28:34 DEBUG    webserver /var/lib/mympd/myMPD/src/web_server.c:132: Using certificate: /var/lib/mympd/ssl/server.pem
10:28:34 DEBUG    webserver /var/lib/mympd/myMPD/src/web_server.c:133: Using private key: /var/lib/mympd/ssl/server.key
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State smartpls: false
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State smartpls_prefix: myMPDsmart
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State smartpls_interval: 14400
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State smartpls_generate_tag_list: Genre
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State last_played_count: 500
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State auto_play: false
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State jukebox_mode: 0
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State jukebox_playlist: Database
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State jukebox_queue_length: 2
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State jukebox_last_played: 24
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State jukebox_unique_tag: Title
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State cols_queue_current: ["Pos","Artist","Album","Track","Title","stickerPlayCount"]
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State cols_search: ["Artist","Album","Track","Title","Duration","AlbumArtist","stickerPlayCount"]
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State cols_browse_database_detail: ["Track","Title","Duration"]
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State cols_browse_playlists_detail: ["Pos","Title","Artist","Album","Duration"]
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State cols_browse_filesystem: ["Artist","Track","Title","stickerPlayCount"]
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State cols_playback: ["Artist","Album","Date","Fileformat","Filetype","AlbumArtist","stickerPlayCount"]
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State cols_queue_last_played: ["Pos","Title","Artist","LastPlayed"]
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State cols_queue_jukebox: ["Pos","Title","Artist","Album"]
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State coverimage_names: folder, cover
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State music_directory: auto
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State playlist_directory: /var/lib/mpd/playlists
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State booklet_name: booklet.pdf
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State volume_min: 0
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State volume_max: 100
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State volume_step: 5
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State webui_settings: {}
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State mpd_stream_port: 8080
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State lyrics_uslt_ext: txt
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State lyrics_sylt_ext: lrc
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State lyrics_vorbis_uslt: LYRICS
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State lyrics_vorbis_sylt: SYNCEDLYRICS
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/state_files.c:70: State covercache_keep_days: 7
10:28:34 INFO     mympdapi  /var/lib/mympd/myMPD/src/mympd_api/mympd_api_timer.c:483: Read 0 timer(s) from disc
10:28:34 INFO     mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_trigger.c:234: Read 0 triggers(s) from disc
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mympd_api.c:85: Setting timer action "clear covercache" to periodic each 7200s
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mympd_api/mympd_api_timer.c:183: Added timer with id 1, start time in 60s
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mpd_client.c:190: MPD connecting to socket /run/mpd/socket
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mpd_client.c:226: MPD connected
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/utility.c:38: Push websocket notify to queue: {"jsonrpc":"2.0","method":"mpd_connected"}
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:45: MPD protocoll version: 0.22.0
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:138: MPD supports albumart
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:134: MPD supports fingerprint
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:130: MPD supports playlists
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:147: MPD supports mounts
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:143: MPD supports readpicture
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:126: MPD supports stickers
10:28:34 INFO     mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:264: Music directory is "/mnt/NAS/Music"
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/utility.c:212: MPD music_directory: "/mnt/NAS/Music"
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:272: Enabling featLibrary support
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:63: Enabling all mpd tag types
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:213: MPD supported tags: Artist Album AlbumArtist Title Track Name Genre Date Composer Performer Comment Disc
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:174: Enabled tag_list: Artist Album AlbumArtist Title Track Genre Date Disc
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:71: Setting interesting mpd tag types
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:174: Enabled tag_list_search: Artist Album AlbumArtist Title Genre
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:174: Enabled tag_list_browse: Artist Album AlbumArtist Genre
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:174: Enabled smartpls_generate_tag_list: Genre
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:74: Enabling single oneshot feature
10:28:34 INFO     mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:76: Enabling advanced search
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:85: Enabling partitions feature
10:28:34 WARN     mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_features.c:96: Disabling binarylimit support, depends on mpd >= 0.22.4
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mpd_worker.c:47: Starting mpd_worker thread for MYMPD_API_CACHES_CREATE
10:28:34 NOTICE   mympdapi  /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:174: Enabled smartpls_generate_tag_list: Genre
10:28:34 NOTICE   mpdworker /var/lib/mympd/myMPD/src/mpd_worker.c:108: MPD worker connecting to socket /run/mpd/socket
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mpd_client/mpd_client_trigger.c:102: Trigger event: mympd_connected (-4)
10:28:34 NOTICE   mpdworker /var/lib/mympd/myMPD/src/mpd_worker.c:131: MPD worker connected
10:28:34 INFO     mpdworker /var/lib/mympd/myMPD/src/mpd_worker/mpd_worker_api.c:46: MPD WORKER API request (-1)(0) MYMPD_API_CACHES_CREATE: {"jsonrpc":"2.0","id":0,"method":"MYMPD_API_CACHES_CREATE","params":{}}
10:28:34 INFO     mpdworker /var/lib/mympd/myMPD/src/mpd_worker/mpd_worker_cache.c:93: Creating caches
10:28:34 DEBUG    webserver /var/lib/mympd/myMPD/src/web_server.c:147: Got websocket notify
10:28:34 DEBUG    webserver /var/lib/mympd/myMPD/src/web_server.c:231: No websocket client connected, discarding message: {"jsonrpc":"2.0","method":"mpd_connected"}
10:28:34 DEBUG    webserver /var/lib/mympd/myMPD/src/web_server.c:236: Correcting connection count from 0 to 1
10:28:34 WARN     mpdworker /var/lib/mympd/myMPD/src/mpd_worker/mpd_worker_cache.c:154: Albumcache, skipping "<filepath redacted>"
10:28:34 WARN     mpdworker /var/lib/mympd/myMPD/src/mpd_worker/mpd_worker_cache.c:154: Albumcache, skipping "<filepath redacted>"
10:28:34 WARN     mpdworker /var/lib/mympd/myMPD/src/mpd_worker/mpd_worker_cache.c:154: Albumcache, skipping "<filepath redacted>"
10:28:34 WARN     mpdworker /var/lib/mympd/myMPD/src/mpd_worker/mpd_worker_cache.c:154: Albumcache, skipping "<filepath redacted>"
10:28:34 DEBUG    webserver /var/lib/mympd/myMPD/src/web_server.c:143: Got internal message
10:28:34 WARN     mpdworker /var/lib/mympd/myMPD/src/mpd_worker/mpd_worker_cache.c:154: Albumcache, skipping "<filepath redacted>"
10:28:34 WARN     mpdworker /var/lib/mympd/myMPD/src/mpd_worker/mpd_worker_cache.c:154: Albumcache, skipping "<filepath redacted>"

[ dozens of additional mpd_worker_cache.c warnings ]

10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mpd_client.c:319: Leaving mpd idle mode
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mpd_client.c:354: Handle request
10:28:34 INFO     mympdapi  /var/lib/mympd/myMPD/src/mympd_api/mympd_api_handler.c:82: MYMPD API request (-1)(0) MYMPD_API_TIMER_SET: {"jsonrpc":"2.0","id":0,"method":"MYMPD_API_TIMER_SET","params":{"timeout":10,"interval":14400,"handler":"timer_handler_smartpls_update"}}
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mympd_api/mympd_api_timer.c:183: Added timer with id 2, start time in 10s
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mympd_api/mympd_api_handler.c:1236: Execution time for MYMPD_API_TIMER_SET: 0.000125
10:28:34 DEBUG    mympdapi  /var/lib/mympd/myMPD/src/mpd_client.c:365: Entering mpd idle mode

[ dozens of additional mpd_worker_cache.c warnings ]

10:28:37 ERROR    mpdworker /var/lib/mympd/myMPD/src/mpd_shared.c:107: MPD error: Response line too large (7)
10:28:37 DEBUG    mpdworker /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:71: Setting interesting mpd tag types
10:28:37 ERROR    mpdworker /var/lib/mympd/myMPD/src/mpd_shared.c:107: MPD error: Response line too large (7)
10:28:37 DEBUG    mpdworker /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:71: Setting interesting mpd tag types
10:28:37 ERROR    mpdworker /var/lib/mympd/myMPD/src/mpd_shared.c:107: MPD error: Response line too large (7)
10:28:37 DEBUG    mpdworker /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:71: Setting interesting mpd tag types
10:28:37 ERROR    mpdworker /var/lib/mympd/myMPD/src/mpd_shared.c:107: MPD error: Response line too large (7)
10:28:37 DEBUG    mpdworker /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:71: Setting interesting mpd tag types
10:28:37 ERROR    mpdworker /var/lib/mympd/myMPD/src/mpd_shared.c:107: MPD error: Response line too large (7)
10:28:37 DEBUG    mpdworker /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:71: Setting interesting mpd tag types
10:28:37 ERROR    mpdworker /var/lib/mympd/myMPD/src/mpd_shared.c:107: MPD error: Response line too large (7)
10:28:37 DEBUG    mpdworker /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:71: Setting interesting mpd tag types
10:28:37 ERROR    mpdworker /var/lib/mympd/myMPD/src/mpd_shared.c:107: MPD error: Response line too large (7)
10:28:37 DEBUG    mpdworker /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:71: Setting interesting mpd tag types
10:28:37 ERROR    mpdworker /var/lib/mympd/myMPD/src/mpd_shared.c:107: MPD error: Response line too large (7)
10:28:37 DEBUG    mpdworker /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:71: Setting interesting mpd tag types
10:28:37 ERROR    mpdworker /var/lib/mympd/myMPD/src/mpd_shared.c:107: MPD error: Response line too large (7)
10:28:37 DEBUG    mpdworker /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:71: Setting interesting mpd tag types
10:28:37 ERROR    mpdworker /var/lib/mympd/myMPD/src/mpd_shared.c:107: MPD error: Response line too large (7)
10:28:37 DEBUG    mpdworker /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:71: Setting interesting mpd tag types

[ Same pair of ERROR/DEBUG messages is repeated around 14.000 times before the segfault ]

Segmentation fault

The same behaviour happens if I purge the content of the /var/lib/mympd folder before starting the daemon.

Downgrading to mympd 7.0.2, the mympd server runs fine again.

jcorporation commented 3 years ago

In the release build the htdocs directory is served from compile time embedded files.

In the debug build the htdocs directory is server from disc. Path is hardcoded from compile time. myMPD switches the user to myMPD if startet as root.

Can you add the verbose log of MPD. It is a communication error with MPD.

tsunulukai commented 3 years ago

Here's the nverbose mpd log

Before myMPD startup:

Jul 17 11:35 : avahi: Initializing interface
Jul 17 11:35 : avahi: Client changed to state 2
Jul 17 11:35 : avahi: Client is RUNNING
Jul 17 11:35 : avahi: Registering service _mpd._tcp/Music Player @ mpd-server
Jul 17 11:35 : avahi: Service group changed to state 0
Jul 17 11:35 : avahi: Service group is UNCOMMITED
Jul 17 11:35 : state_file: Loading state file /var/lib/mpd/state
Jul 17 11:35 : config: option 'gapless' on line 231 was not recognized
Jul 17 11:35 : config: option 'gapless_mp3_playback' on line 232 was not recognized
Jul 17 11:35 : avahi: Service group changed to state 1
Jul 17 11:35 : avahi: Service group is REGISTERING
Jul 17 11:35 : avahi: Service group changed to state 2
Jul 17 11:35 : avahi: Service 'Music Player @ mpd-server' successfully established.

after myMPD startup:

Jul 17 11:35 : client: [0] opened from 192.168.1.1:55644
Jul 17 11:35 : client: [0] process command "ping"
Jul 17 11:35 : client: [0] command returned 0
Jul 17 11:35 : client: [0] process command "status"
Jul 17 11:35 : client: [0] command returned 0
Jul 17 11:35 : client: [0] process command "status"
Jul 17 11:35 : client: [0] command returned 0
Jul 17 11:35 : client: [0] process command "outputs"
Jul 17 11:35 : client: [0] command returned 0
Jul 17 11:35 : client: [0] process command "status"
Jul 17 11:35 : client: [0] command returned 0
Jul 17 11:35 : client: [0] process command "status"
Jul 17 11:35 : client: [0] command returned 0
Jul 17 11:35 : client: [0] process command "ping"
Jul 17 11:35 : client: [0] command returned 0
Jul 17 11:35 : client: [0] process command "status"
Jul 17 11:35 : client: [0] command returned 0
Jul 17 11:35 : client: [0] process command "status"
Jul 17 11:35 : client: [0] command returned 0
Jul 17 11:35 : client: [0] process command "outputs"
Jul 17 11:35 : client: [0] command returned 0
Jul 17 11:35 : client: [0] process command "status"
Jul 17 11:35 : client: [0] command returned 0
Jul 17 11:35 : client: [0] process command "status"
Jul 17 11:35 : client: [0] command returned 0
Jul 17 11:35 : client: [0] process command "ping"
Jul 17 11:35 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "outputs"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "ping"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [1] opened from local
Jul 17 11:36 : client: [1] process command "password "<redacted>""
Jul 17 11:36 : client: [1] command returned 0
Jul 17 11:36 : client: [1] process command "commands"
Jul 17 11:36 : client: [1] command returned 0
Jul 17 11:36 : client: [1] process command "config"
Jul 17 11:36 : client: [1] command returned 0
Jul 17 11:36 : client: [1] process command "tagtypes "all""
Jul 17 11:36 : client: [1] command returned 0
Jul 17 11:36 : client: [1] process command "tagtypes"
Jul 17 11:36 : client: [1] command returned 0
Jul 17 11:36 : client: [1] process command list
Jul 17 11:36 : client: process command "tagtypes "clear""
Jul 17 11:36 : client: command returned 0
Jul 17 11:36 : client: process command "tagtypes enable Artist Album AlbumArtist Title Track Genre Date Disc"
Jul 17 11:36 : client: command returned 0
Jul 17 11:36 : client: [1] process command list returned 0
Jul 17 11:36 : client: [1] process command "status"
Jul 17 11:36 : client: [1] command returned 0
Jul 17 11:36 : client: [1] process command "currentsong"
Jul 17 11:36 : client: [1] command returned 0
Jul 17 11:36 : client: [1] process command "idle"
Jul 17 11:36 : client: [1] command returned 1
Jul 17 11:36 : client: [2] opened from local
Jul 17 11:36 : client: [2] process command "password "<redacted>""
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 0:1000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 1000:2000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [1] process command "idle"
Jul 17 11:36 : client: [1] command returned 1
Jul 17 11:36 : client: [2] process command "search file "" window 2000:3000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 3000:4000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "outputs"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 4000:5000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 5000:6000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 6000:7000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 7000:8000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 8000:9000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 9000:10000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 10000:11000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 11000:12000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "ping"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 12000:13000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 13000:14000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 14000:15000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 15000:16000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 16000:17000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 17000:18000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 18000:19000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 19000:20000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "outputs"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 20000:21000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 21000:22000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [2] process command "search file "" window 22000:23000"
Jul 17 11:36 : client: [2] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "ping"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [2] closed
Jul 17 11:36 : client: [1] closed
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "outputs"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "ping"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "status"
Jul 17 11:36 : client: [0] command returned 0
Jul 17 11:36 : client: [0] process command "outputs"
Jul 17 11:36 : client: [0] command returned 0

Using socat to intercept the communications between myMPD and the mpd server, I don't see any command exchange between them when the following error repeats in loop:

socat -v UNIX-LISTEN:/run/mpd/socket,mode=777,reuseaddr,fork UNIX-CONNECT:/run/mpd/mysocket | tee debugsocket.log

11:57:36 DEBUG    mpdworker /var/lib/mympd/myMPD/src/mpd_shared/mpd_shared_tags.c:71: Setting interesting mpd tag types
11:57:36 ERROR    mpdworker /var/lib/mympd/myMPD/src/mpd_shared.c:107: MPD error: Response line too large (7)

I've sent you the complete logs by email.

jcorporation commented 3 years ago

Thanks for debugs. There are very helpfull.

I found two problems:

  1. myMPD does not set interesting tag types for the worker thread. MPD sends all tags and one file has a comment tag that is longer than libmpdclients max line length.
  2. Error handling for this scenario is not correctly implemented.

Disable the comment tag in the mpd configuration as a workarround.

There is already an issue open in the libmpdclient repository: https://github.com/MusicPlayerDaemon/libmpdclient/issues/69

jcorporation commented 3 years ago

I added a pull request to increase the buffer size of libmpdclient to 8192 (same as in MPD) and make it configurable at compile time.

https://github.com/MusicPlayerDaemon/libmpdclient/pull/74

tsunulukai commented 3 years ago

Disabling the comment tag in the mpd "metadata_to_use" config entry does indeed provide a workaround to this issue. I'll be using that pending the definitive fix. Thanks for your quick feedback on this !

jcorporation commented 3 years ago

I investigated a bit more. It seems that each tag value that exceeds the 4096 byte buffer limit of libmpdclient causes the response line to large error. The mpd output size is configureable and defaults to 8 MiB.

Disabling the commet tag or setting the buffer size to a higher value are only workarounds.

libmpdclients needs a dynamic growing buffer or mpd must limit the max line length to fix this issue.

tsunulukai commented 3 years ago

How comes this problem didn't happen with the previous version of mympd ? What changed in the way this is handled ?

jcorporation commented 3 years ago

The cause was the missing tagtypes command in the mpd_worker thread. I think you have not enabled this tag in myMPD only in MPD.

With enabled comment tag the issue should appear with each mp dclient that uses libmpdclient.

jcorporation commented 3 years ago

I am closing this issue. I increased the buffer to 32768 bytes. I thinks this little bit more memory overhead is acceptable.