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

On DietPi, myMPD stops connecting to MPD after running for several hours #1209

Closed jalsco closed 5 months ago

jalsco commented 9 months ago 
myMPD 14.0.0
Music Player Daemon 0.22.6 (0.22.6)
DietPi v9.0.2
OS: Debian GNU/Linux 11 (bullseye) aarch64
Host: Radxa ROCK Pi 4B
Kernel: 6.1.63-current-rockchip64

MyMPD runs great, from all web browsers on multiple devices (windows, iOS, etc) for "a while". By that I mean there is no specific pattern of how long it takes. It can be anywhere from a couple hours to a couple days. But then MyMPD stops running, even though MPD keeps running evidenced by fact that the music keeps playing until the queue is exhausted.

After this happens ALL web clients, on all devices, will see the red (!) message: MPD connection error: No such file or directory flashing up every few seconds in the bottom right corner of the screen. And red (!) message: MPD disconnected elsewhere on the screen.

On the DietPi machine the myMPD service shows: 

[Tue Feb 06] root@batopi: ~$ service mympd status
● mympd.service - myMPD server daemon
     Loaded: loaded (/lib/systemd/system/mympd.service; enabled; vendor preset: enabled)
     Active: active (running) since Tue 2024-02-06 02:36:12 EST; 1h 37min ago
       Docs: man:mympd(1)
   Main PID: 3217 (mympd)
      Tasks: 3 (limit: 2203)
     Memory: 3.8M
        CPU: 1.956s
     CGroup: /system.slice/mympd.service
             └─3217 /usr/bin/mympd

Feb 06 04:12:53 batopi mympd[3217]: ERROR    mympdapi  "default": Connection: No such file or directory
Feb 06 04:12:58 batopi mympd[3217]: ERROR    mympdapi  "default": Connection: No such file or directory
Feb 06 04:13:03 batopi mympd[3217]: ERROR    mympdapi  "default": Connection: No such file or directory
Feb 06 04:13:08 batopi mympd[3217]: ERROR    mympdapi  "default": Connection: No such file or directory
Feb 06 04:13:13 batopi mympd[3217]: ERROR    mympdapi  "default": Connection: No such file or directory
Feb 06 04:13:18 batopi mympd[3217]: ERROR    mympdapi  "default": Connection: No such file or directory
Feb 06 04:13:23 batopi mympd[3217]: ERROR    mympdapi  "default": Connection: No such file or directory
Feb 06 04:13:28 batopi mympd[3217]: ERROR    mympdapi  "default": Connection: No such file or directory
Feb 06 04:13:33 batopi mympd[3217]: ERROR    mympdapi  "default": Connection: No such file or directory
Feb 06 04:13:38 batopi mympd[3217]: ERROR    mympdapi  "default": Connection: No such file or directory
[Tue Feb 06] root@batopi: ~$

Steps to reproduce the behavior:

  1. Go to MyMPD on webbrowser, load up a playlist with a few hours of music, and start it playing.
  2. Wait - maybe later in the afternoon or next day - the website will just stop responding, as described above.

Happens every single time - never takes longer than a day and a half.

Expected behavior

Runs forever without MPD becoming disconnected,

Screenshots

This from Windows , Firefox, bottom corner of Browser after a screen reload :

image

Some things tried

None of these make any difference. The problem just keeps on going exactly the same.

Something that works every single time to fix it sudo reboot now

Of course that is impractical - but it is the only thing I have found that works. Some webpages are hosted on my machine, and also other services so that I cannot just be rebooting it each day (because the music menus stopped responding). After reboot the status shows as follows: 

[Tue Feb 06] root@batopi: ~$ service mympd status
● mympd.service - myMPD server daemon
     Loaded: loaded (/lib/systemd/system/mympd.service; enabled; vendor preset: enabled)
     Active: active (running) since Tue 2024-02-06 04:31:11 EST; 15s ago
       Docs: man:mympd(1)
   Main PID: 805 (mympd)
      Tasks: 3 (limit: 2203)
     Memory: 5.5M
        CPU: 388ms
     CGroup: /system.slice/mympd.service
             └─805 /usr/bin/mympd

Feb 06 04:31:11 batopi mympd[805]: NOTICE   mympd     Config dir: "/var/lib/mympd/config"
Feb 06 04:31:11 batopi mympd[805]: NOTICE   mympd     Setting loglevel to WARN
Feb 06 04:31:11 batopi mympd[805]: WARN     mympdapi  "default": Disabling delete playlist range feature, depends on mpd >= 0.23.3
Feb 06 04:31:11 batopi mympd[805]: WARN     mympdapi  "default": Disabling position whence feature, depends on mpd >= 0.23.5
Feb 06 04:31:11 batopi mympd[805]: WARN     mympdapi  "default": Disabling advanced queue feature, depends on mpd >= 0.24.0
Feb 06 04:31:11 batopi mympd[805]: WARN     mympdapi  "default": Disabling consume oneshot feature, depends on mpd >= 0.24.0
Feb 06 04:31:11 batopi mympd[805]: WARN     mympdapi  "default": Disabling playlist directory autoconfiguration feature, depends on mpd >= 0.24.0
Feb 06 04:31:11 batopi mympd[805]: WARN     mympdapi  "default": Disabling starts_with filter expression feature, depends on mpd >= 0.24.0
Feb 06 04:31:11 batopi mympd[805]: WARN     mympdapi  "default": Disabling db added feature, depends on mpd >= 0.24.0

Even if there were some other way I could reload it , without rebooting the whole system, I'd be happy to do that... Like some way to reset a problematic socket ?? or mem leak or buffer overrun ?? I have no idea the cause 🤷🏻‍♂️

jcorporation commented 9 months ago

Strange issue. Please provide MPD verbose logs and myMPD debug logs.

jalsco commented 9 months ago

Thanks for fast reply 🙏🏻😊 I went to /etc/mpd.conf and changed loglevel to verbose and restart MPD service. Then for MyMPD in /var/lib/private/mympd/config/loglevel I change to 7 and restart the myMPD service. I hope that what you meant for logging ? 

[Tue Feb 06] root@batopi: ~$ service mpd status
● mpd.service - Music Player Daemon
     Loaded: loaded (/lib/systemd/system/mpd.service; enabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/mpd.service.d
             └─dietpi.conf
     Active: active (running) since Tue 2024-02-06 19:59:40 EST; 6s ago
TriggeredBy: ● mpd.socket
       Docs: man:mpd(1)
             man:mpd.conf(5)
             file:///usr/share/doc/mpd/html/user.html
   Main PID: 8707 (mpd)
      Tasks: 6 (limit: 2203)
     Memory: 16.8M
        CPU: 1.286s
     CGroup: /system.slice/mpd.service
             └─8707 /usr/bin/mpd --no-daemon

Feb 06 19:59:47 batopi mpd[8707]: client: process command "tagtypes "clear""
Feb 06 19:59:47 batopi mpd[8707]: client: command returned 0
Feb 06 19:59:47 batopi mpd[8707]: client: process command "tagtypes enable Artist Album AlbumArtist Title Genre Date OriginalDate Disc MUSICBRAINZ_ARTISTID MUSICBRAINZ_ALBUMID MUSICBRAINZ_ALBUMARTISTID MUSICB>
Feb 06 19:59:47 batopi mpd[8707]: client: command returned 0
Feb 06 19:59:47 batopi mpd[8707]: client: [3] process command list returned 0
Feb 06 19:59:47 batopi mpd[8707]: client: [3] process command "stats"
Feb 06 19:59:47 batopi mpd[8707]: client: [3] command returned 0
Feb 06 19:59:47 batopi mpd[8707]: client: [3] closed
Feb 06 19:59:47 batopi mpd[8707]: client: [1] process command "idle database stored_playlist playlist player mixer output options update partition"
Feb 06 19:59:47 batopi mpd[8707]: client: [1] command returned 1
lines 1-26/26 (END)
[Tue Feb 06] root@batopi: ~$ service mympd status
● mympd.service - myMPD server daemon
     Loaded: loaded (/lib/systemd/system/mympd.service; enabled; vendor preset: enabled)
     Active: active (running) since Tue 2024-02-06 19:49:58 EST; 50s ago
       Docs: man:mympd(1)
   Main PID: 8639 (mympd)
      Tasks: 3 (limit: 2203)
     Memory: 2.0M
        CPU: 182ms
     CGroup: /system.slice/mympd.service
             └─8639 /usr/bin/mympd

Feb 06 19:50:47 batopi mympd[8639]: DEBUG    mympdapi  "stickerdb": Exiting idle mode
Feb 06 19:50:47 batopi mympd[8639]: DEBUG    mympdapi  "stickerdb": Entering idle mode
Feb 06 19:50:47 batopi mympd[8639]: DEBUG    mympdapi  Queue event
Feb 06 19:50:47 batopi mympd[8639]: DEBUG    mympdapi  Queue "mympd_api_queue": 0 entries
Feb 06 19:50:47 batopi mympd[8639]: DEBUG    mympdapi  "default": Queue event
Feb 06 19:50:47 batopi mympd[8639]: DEBUG    mympdapi  "default": Leaving mpd idle mode
Feb 06 19:50:47 batopi mympd[8639]: DEBUG    mympdapi  "default": Handle API request "INTERNAL_API_TRIGGER_EVENT_EMIT"
Feb 06 19:50:47 batopi mympd[8639]: DEBUG    mympdapi  "default": MYMPD API request (0)(0) INTERNAL_API_TRIGGER_EVENT_EMIT: {"jsonrpc":"2.0","id":0,"method":"INTERNAL_API_TRIGGER_EVENT_EMIT","params":{"event">
Feb 06 19:50:47 batopi mympd[8639]: DEBUG    mympdapi  "default": Trigger event: mympd_disconnected (-5)
Feb 06 19:50:47 batopi mympd[8639]: DEBUG    mympdapi  "default": Entering mpd idle mode

Now I will just let the music play and wait for next fail. I will send all the details from MyMPD's log/journal when that happens. Probably will be several hours later in my work day which is just starting now.

By the way - MyMPD is awesome ! and everyone here loves it . Thank you 💖

jcorporation commented 9 months ago

Yes, this are the correct log settings.

jalsco commented 9 months ago

Here is the output after a day of playing. It seems like connections still active. Still monitoring. 

[Fri Feb 09] root@batopi: ~$ service mpd status
● mpd.service - Music Player Daemon
     Loaded: loaded (/lib/systemd/system/mpd.service; enabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/mpd.service.d
             └─dietpi.conf
     Active: active (running) since Thu 2024-02-08 02:36:24 EST; 22h ago
TriggeredBy: ● mpd.socket
       Docs: man:mpd(1)
             man:mpd.conf(5)
             file:///usr/share/doc/mpd/html/user.html
   Main PID: 25164 (mpd)
      Tasks: 6 (limit: 2203)
     Memory: 53.8M
        CPU: 35min 59.613s
     CGroup: /system.slice/mpd.service
             └─25164 /usr/bin/mpd --no-daemon

Feb 09 01:00:56 batopi mpd[25164]: client: [2] process command "outputs"
Feb 09 01:00:56 batopi mpd[25164]: client: [2] command returned 0
Feb 09 01:00:56 batopi mpd[25164]: client: [2] process command "channels"
Feb 09 01:00:56 batopi mpd[25164]: client: [2] command returned 0
Feb 09 01:00:57 batopi mpd[25164]: client: [2] process command "status"
Feb 09 01:00:57 batopi mpd[25164]: client: [2] command returned 0
Feb 09 01:00:57 batopi mpd[25164]: client: [2] process command "outputs"
Feb 09 01:00:57 batopi mpd[25164]: client: [2] command returned 0
Feb 09 01:00:57 batopi mpd[25164]: client: [2] process command "channels"
Feb 09 01:00:57 batopi mpd[25164]: client: [2] command returned 0
[Fri Feb 09] root@batopi: ~$ service mympd status
● mympd.service - myMPD server daemon
     Loaded: loaded (/lib/systemd/system/mympd.service; enabled; vendor preset: enabled)
     Active: active (running) since Thu 2024-02-08 02:36:25 EST; 22h ago
       Docs: man:mympd(1)
   Main PID: 25175 (mympd)
      Tasks: 3 (limit: 2203)
     Memory: 4.9M
        CPU: 8.057s
     CGroup: /system.slice/mympd.service
             └─25175 /usr/bin/mympd

Feb 09 00:17:51 batopi mympd[25175]: DEBUG    mympdapi  "default": MYMPD API request (274)(851913016) MYMPD_API_QUEUE_SEARCH: {"jsonrpc":"2.0","id":851913016,"method":"MYMPD_API_QUEUE_SEARCH","params":{"offse>
Feb 09 00:17:51 batopi mympd[25175]: DEBUG    mympdapi  Push response to queue for connection 274: {"jsonrpc":"2.0","id":851913016,"result":{"method":"MYMPD_API_QUEUE_SEARCH","data":[],"totalTime":0,"totalEnt>
Feb 09 00:17:51 batopi mympd[25175]: DEBUG    mympdapi  "default": Entering mpd idle mode
Feb 09 00:17:51 batopi mympd[25175]: DEBUG    webserver Queue "web_server_queue": 0 entries
Feb 09 00:17:51 batopi mympd[25175]: DEBUG    webserver "default": Got API response for id "274"
Feb 09 00:17:51 batopi mympd[25175]: DEBUG    webserver "default": Sending response to conn_id "274" (length: 151): {"jsonrpc":"2.0","id":851913016,"result":{"method":"MYMPD_API_QUEUE_SEARCH","data":[],"total>
Feb 09 00:17:51 batopi mympd[25175]: DEBUG    webserver Sending 151 bytes to 274
Feb 09 00:17:55 batopi mympd[25175]: INFO     webserver HTTP connection "268" closed
Feb 09 00:19:46 batopi mympd[25175]: INFO     webserver HTTP connection "274" closed
Feb 09 00:19:46 batopi mympd[25175]: INFO     webserver HTTP connection "273" closed
lines 1-21/21 (END)
jcorporation commented 9 months ago

Is there a further mpdclient connecting to this MPD instance?

jalsco commented 9 months ago

several clients connect - 2 different windows machines, 2 iOS devices (14.5.1 and 12.5.7 ) via either Firefox or Safari on each device. Rarely other devices.

It is still running now (2 days later). The only change I made was setting the logging. I am still expecting it to fail some time soon. Young daughter in the past has rebooted it when her music stops, but assures me that she has not in last 2 days.

jalsco commented 9 months ago 
[Fri Feb 09] root@batopi: ~$ apt upgrade
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
Calculating upgrade... Done
The following packages will be upgraded:
  mympd
1 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
Need to get 775 kB of archives.
After this operation, 4096 B disk space will be freed.
Do you want to continue? [Y/n] Y
Err:1 https://download.opensuse.org/repositories/home:/jcorporation/Debian_11  mympd 14.0.1-1
  500  Internal Server Error [IP: 195.135.223.226 443]
E: Failed to fetch https://download.opensuse.org/repositories/home:/jcorporation/Debian_11/arm64/mympd_14.0.1-1_arm64.deb  500  Internal Server Error [IP: 195.135.223.226 443]
E: Unable to fetch some archives, maybe run apt-get update or try with --fix-missing?
[Fri Feb 09] root@batopi: ~$

Was there an update for DietPi ?

I also have ympd installed, but I may uninstall that as it is rarely used.

jcorporation commented 9 months ago

I released myMPD 14.0.1

jcorporation commented 8 months ago

Any updates for this issue?

jalsco commented 8 months ago

It looks like the issue is resolved. It has been running now for several days without those symptoms that I reported . Please close this Issue now, and if needed (like the problems return), then I can re-open this Issue.

jalsco commented 6 months ago

Problem is happening again 😢 Please re-open this Issue . I do not know for how long it has been happening as I have been away from this site for several weeks.

Now that server, batopi (running dietpi) , is on myMPD 15.0.1

[Fri May 10] root@batopi: ~$ service mympd status
● mympd.service - myMPD server daemon
     Loaded: loaded (/lib/systemd/system/mympd.service; enabled; vendor preset: enabled)
     Active: active (running) since Fri 2024-05-10 19:56:42 EDT; 11min ago
       Docs: man:mympd(1)
   Main PID: 64709 (mympd)
      Tasks: 3 (limit: 2123)
     Memory: 2.4M
        CPU: 789ms
     CGroup: /system.slice/mympd.service
             └─64709 /usr/bin/mympd

May 10 20:07:37 batopi mympd[64709]: DEBUG    webserver "default": Sending notify to conn_id "20": {"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection er>
May 10 20:07:37 batopi mympd[64709]: DEBUG    webserver "default": Sending notify to conn_id "3": {"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection err>
May 10 20:07:42 batopi mympd[64709]: DEBUG    mympdapi  "default": Connect event
May 10 20:07:42 batopi mympd[64709]: INFO     mympdapi  "default": Creating mpd connection for partition "default"
May 10 20:07:42 batopi mympd[64709]: NOTICE   mympdapi  "default": Connecting to socket "/var/run/mpd/socket"
May 10 20:07:42 batopi mympd[64709]: ERROR    mympdapi  "default": Connection: No such file or directory
May 10 20:07:42 batopi mympd[64709]: DEBUG    mympdapi  "default": Push websocket notify to queue: "{"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection e>
May 10 20:07:42 batopi mympd[64709]: DEBUG    webserver Queue "web_server_queue": 0 entries
May 10 20:07:42 batopi mympd[64709]: DEBUG    webserver "default": Sending notify to conn_id "20": {"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection er>
May 10 20:07:42 batopi mympd[64709]: DEBUG    webserver "default": Sending notify to conn_id "3": {"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection err>
lines 1-21/21 (END)

image

jcorporation commented 6 months ago
jalsco commented 6 months ago

Yesterday, after few weeks of not using it, the messages and screenshots above were encountered. So did a sudo reboot now to fix the problem and played music without incident for several hours for the rest of that day. This morning upon trying to myMPD I get the same messages again. 

[Sat May 11] root@batopi: ~$ ls -l /var/run/mpd/socket
ls: cannot access '/var/run/mpd/socket': No such file or directory
[Sat May 11] root@batopi: ~$

I assume MPC is a console based operation of MPD ? It is not installed, I will check and find it (but I expect it would work) as Status of MPD and MyMPD are green. 

[Sat May 11] root@batopi: ~$ service mympd status
● mympd.service - myMPD server daemon
     Loaded: loaded (/lib/systemd/system/mympd.service; enabled; vendor preset: enabled)
     Active: active (running) since Sat 2024-05-11 02:37:02 EDT; 18h ago
       Docs: man:mympd(1)
   Main PID: 5790 (mympd)
      Tasks: 3 (limit: 2123)
     Memory: 2.8M
        CPU: 33.288s
     CGroup: /system.slice/mympd.service
             └─5790 /usr/bin/mympd

May 11 20:40:57 batopi mympd[5790]: DEBUG    mympdapi  "default": Push websocket notify to queue: "{"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection er>
May 11 20:40:57 batopi mympd[5790]: DEBUG    webserver Queue "web_server_queue": 0 entries
May 11 20:40:57 batopi mympd[5790]: DEBUG    webserver "default": Sending notify to conn_id "620": {"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection er>
May 11 20:41:02 batopi mympd[5790]: DEBUG    mympdapi  "default": Connect event
May 11 20:41:02 batopi mympd[5790]: INFO     mympdapi  "default": Creating mpd connection for partition "default"
May 11 20:41:02 batopi mympd[5790]: NOTICE   mympdapi  "default": Connecting to socket "/var/run/mpd/socket"
May 11 20:41:02 batopi mympd[5790]: ERROR    mympdapi  "default": Connection: No such file or directory
May 11 20:41:02 batopi mympd[5790]: DEBUG    mympdapi  "default": Push websocket notify to queue: "{"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection er>
May 11 20:41:02 batopi mympd[5790]: DEBUG    webserver Queue "web_server_queue": 0 entries
May 11 20:41:02 batopi mympd[5790]: DEBUG    webserver "default": Sending notify to conn_id "620": {"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection er>

About "verbose logs" a few month ago when this reported, I did enable verbose logging. IT has been that way since then. Please direct me to where the log file will be (I have been searching) ?

jalsco commented 6 months ago

I think this 👇 is the logs. Please advise if the logs are different to that. 

[Sat May 11] root@batopi: ~$ journalctl -fu mympd
Journal file /var/log/journal/cb0595162f264c0fb73bbfc15e7e6256/system.journal is truncated, ignoring file.
-- Journal begins at Sat 2024-05-11 18:59:32 EDT. --
May 11 20:54:12 batopi mympd[5790]: DEBUG    mympdapi  "default": Push websocket notify to queue: "{"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection error: %{error}","data":{"error":"No such file or directory"}}}"
May 11 20:54:12 batopi mympd[5790]: DEBUG    webserver Queue "web_server_queue": 0 entries
May 11 20:54:12 batopi mympd[5790]: DEBUG    webserver "default": Sending notify to conn_id "620": {"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection error: %{error}","data":{"error":"No such file or directory"}}}
May 11 20:54:17 batopi mympd[5790]: DEBUG    mympdapi  "default": Connect event
May 11 20:54:17 batopi mympd[5790]: INFO     mympdapi  "default": Creating mpd connection for partition "default"
May 11 20:54:17 batopi mympd[5790]: NOTICE   mympdapi  "default": Connecting to socket "/var/run/mpd/socket"
May 11 20:54:17 batopi mympd[5790]: ERROR    mympdapi  "default": Connection: No such file or directory
May 11 20:54:17 batopi mympd[5790]: DEBUG    mympdapi  "default": Push websocket notify to queue: "{"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection error: %{error}","data":{"error":"No such file or directory"}}}"
May 11 20:54:17 batopi mympd[5790]: DEBUG    webserver Queue "web_server_queue": 0 entries
May 11 20:54:17 batopi mympd[5790]: DEBUG    webserver "default": Sending notify to conn_id "620": {"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection error: %{error}","data":{"error":"No such file or directory"}}}
May 11 20:54:22 batopi mympd[5790]: DEBUG    mympdapi  "default": Connect event
May 11 20:54:22 batopi mympd[5790]: INFO     mympdapi  "default": Creating mpd connection for partition "default"
May 11 20:54:22 batopi mympd[5790]: NOTICE   mympdapi  "default": Connecting to socket "/var/run/mpd/socket"
May 11 20:54:22 batopi mympd[5790]: ERROR    mympdapi  "default": Connection: No such file or directory
May 11 20:54:22 batopi mympd[5790]: DEBUG    mympdapi  "default": Push websocket notify to queue: "{"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection error: %{error}","data":{"error":"No such file or directory"}}}"
May 11 20:54:22 batopi mympd[5790]: DEBUG    webserver Queue "web_server_queue": 0 entries
May 11 20:54:22 batopi mympd[5790]: DEBUG    webserver "default": Sending notify to conn_id "620": {"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection error: %{error}","data":{"error":"No such file or directory"}}}
May 11 20:54:27 batopi mympd[5790]: DEBUG    mympdapi  "default": Connect event
May 11 20:54:27 batopi mympd[5790]: INFO     mympdapi  "default": Creating mpd connection for partition "default"
May 11 20:54:27 batopi mympd[5790]: NOTICE   mympdapi  "default": Connecting to socket "/var/run/mpd/socket"
May 11 20:54:27 batopi mympd[5790]: ERROR    mympdapi  "default": Connection: No such file or directory
May 11 20:54:27 batopi mympd[5790]: DEBUG    mympdapi  "default": Push websocket notify to queue: "{"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection error: %{error}","data":{"error":"No such file or directory"}}}"
May 11 20:54:27 batopi mympd[5790]: DEBUG    webserver Queue "web_server_queue": 0 entries
May 11 20:54:27 batopi mympd[5790]: DEBUG    webserver "default": Sending notify to conn_id "620": {"jsonrpc":"2.0","method":"notify","params":{"facility":"mpd","severity":"error","message":"MPD connection error: %{error}","data":{"error":"No such file or directory"}}}
jalsco commented 6 months ago

For anyone else on DietPi reading this thread.

Install mpc :
sudo apt-get -y install mpc Usage found in: mpc help

Note also @MichaIng comment from July 2019: "I am just not sure, since MPD runs as user "mpd", if you need to start mpc then as well via sudo -u mpd mpc to have the same home/XDG directories and possible included settings/flag files applied. "

MPC is now installed and working 👇, but cannot draw immediate conclusions as (my assistant) rebooted DietPi and started some music using MyMPD before MPC was installed. Next time the sockets problem shows up I can test if MPC is still working at that time. 

[Sat May 11] root@batopi: ~$ sudo -u mpd mpc queued
Justin Bieber - Ghost
[Sat May 11] root@batopi: ~$ sudo -u mpd mpc pause
Rihanna - Umbrella
[paused]  #1/8   0:44/4:02 (18%)
volume: 57%   repeat: off   random: off   single: off   consume: on
[Sat May 11] root@batopi: ~$ sudo -u mpd mpc pause
Rihanna - Umbrella
[paused]  #1/8   0:44/4:02 (18%)
volume: 57%   repeat: off   random: off   single: off   consume: on
[Sat May 11] root@batopi: ~$ sudo -u mpd mpc play
Rihanna - Umbrella
[playing] #1/8   0:45/4:02 (18%)
volume: 57%   repeat: off   random: off   single: off   consume: on
[Sat May 11] root@batopi: ~$
jcorporation commented 6 months ago

ls: cannot access '/var/run/mpd/socket': No such file or directory

This is the problem. The MPD socket is gone. It seems it is not a myMPD bug.

jalsco commented 6 months ago

The same problem recurred now. I can confirm that while myMPD is not working with this problem, using MPC does work

jalsco commented 6 months ago

So, if myMPD is not cause of the problem, then which component is the one responsible for the problem ?? MPD ?? or DietPi ?? or something else ??

Until this problem we only using myMPD for our music. That's the client we like the best.

Please advise what is next step for me to follow up, because it is a real problem ? 🤷🏻‍♂️

@MichaIng

jcorporation commented 6 months ago

How does mpc connect to MPD? You should not start mpc with sudo, but with a normal user account.

I need more information from the time the error occurs:

I think mpc connects to localhost:6600 if there is no socket. That could be the reason why mpc works and myMPD not.

MichaIng commented 6 months ago

MPD is not running, obviously. Check:

journalctl -u mpd
jalsco commented 6 months ago

I really think that MPD is running, as it has green "active (running)" status when checked with service mpd status And also music can be played using MPC when this problem occurs.

The problem seems to be that the socket drops out, and thus doesn't exist anymore, as shown by ls -l /var/run/mpd/socket .

Also - restarting MPD - has no effect on the problem, but rebooting whole system fixes it.

jalsco commented 6 months ago

MPD def running and can play music via MPC, but the socket that myMPD was using doesn't exist 👇 

[Sun May 12] root@batopi: ~$ ls -l /var/run/mpd/socket
ls: cannot access '/var/run/mpd/socket': No such file or directory
[Sun May 12] root@batopi: ~$ service mpd status
● mpd.service - Music Player Daemon
     Loaded: loaded (/lib/systemd/system/mpd.service; enabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/mpd.service.d
             └─dietpi.conf
     Active: active (running) since Sun 2024-05-12 21:58:46 EDT; 10min ago
TriggeredBy: ● mpd.socket
       Docs: man:mpd(1)
             man:mpd.conf(5)
             file:///usr/share/doc/mpd/html/user.html
   Main PID: 3510 (mpd)
      Tasks: 3 (limit: 2123)
     Memory: 8.9M
        CPU: 466ms
     CGroup: /system.slice/mpd.service
             └─3510 /usr/bin/mpd --no-daemon

May 12 21:58:46 batopi mpd[3510]: exception: Input plugin 'tidal' is not configured: No Tidal application token configured
May 12 21:58:46 batopi mpd[3510]: exception: Input plugin 'qobuz' is not configured: No Qobuz app_id configured
May 12 21:58:46 batopi mpd[3510]: curl: version 7.74.0
May 12 21:58:46 batopi mpd[3510]: curl: with GnuTLS/3.7.1
May 12 21:58:46 batopi mpd[3510]: zeroconf: No global port, disabling zeroconf
May 12 21:58:46 batopi mpd[3510]: state_file: Loading state file /mnt/dietpi_userdata/.mpd_cache/state
May 12 21:58:46 batopi mpd[3510]: inotify: initializing inotify
May 12 21:58:46 batopi mpd[3510]: exception: U_INVALID_CHAR_FOUND
May 12 21:58:46 batopi mpd[3510]: inotify: watching music directory
May 12 21:58:46 batopi systemd[1]: Started Music Player Daemon.
[Sun May 12] root@batopi: ~$ journalctl -u mpd
Journal file /var/log/journal/cb0595162f264c0fb73bbfc15e7e6256/system.journal is truncated, ignoring file.
-- Journal begins at Sun 2024-05-12 21:02:08 EDT, ends at Sun 2024-05-12 22:09:25 EDT. --
May 12 21:02:08 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:08 batopi mpd[491]: client: [2] process command "channels"
May 12 21:02:08 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:09 batopi mpd[491]: client: [2] process command "status"
May 12 21:02:09 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:09 batopi mpd[491]: client: [2] process command "outputs"
May 12 21:02:09 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:09 batopi mpd[491]: client: [2] process command "channels"
May 12 21:02:09 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:10 batopi mpd[491]: client: [2] process command "status"
May 12 21:02:10 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:10 batopi mpd[491]: client: [2] process command "outputs"
May 12 21:02:10 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:10 batopi mpd[491]: client: [2] process command "channels"
May 12 21:02:10 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:11 batopi mpd[491]: client: [2] process command "status"
May 12 21:02:11 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:11 batopi mpd[491]: client: [2] process command "outputs"
May 12 21:02:11 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:11 batopi mpd[491]: client: [2] process command "channels"
May 12 21:02:11 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:12 batopi mpd[491]: client: [2] process command "status"
May 12 21:02:12 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:12 batopi mpd[491]: client: [2] process command "outputs"
May 12 21:02:12 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:12 batopi mpd[491]: client: [2] process command "channels"
May 12 21:02:12 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:13 batopi mpd[491]: client: [2] process command "status"
May 12 21:02:13 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:13 batopi mpd[491]: client: [2] process command "outputs"
May 12 21:02:13 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:13 batopi mpd[491]: client: [2] process command "channels"
May 12 21:02:13 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:14 batopi mpd[491]: client: [2] process command "status"
May 12 21:02:14 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:14 batopi mpd[491]: client: [2] process command "outputs"
May 12 21:02:14 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:14 batopi mpd[491]: client: [2] process command "channels"
May 12 21:02:14 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:15 batopi mpd[491]: client: [2] process command "status"
May 12 21:02:15 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:15 batopi mpd[491]: client: [2] process command "outputs"
May 12 21:02:15 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:15 batopi mpd[491]: client: [2] process command "channels"
May 12 21:02:15 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:16 batopi mpd[491]: client: [2] process command "status"
May 12 21:02:16 batopi mpd[491]: client: [2] command returned 0
May 12 21:02:16 batopi mpd[491]: client: [2] process command "outputs"

[Sun May 12] root@batopi: ~$ sudo -u mpd mpc play
Tones and I - Dance Monkey
[playing] #1/1   0:00/4:11 (0%)
volume: 44%   repeat: off   random: off   single: off   consume: on
[Sun May 12] root@batopi: ~$ sudo -u mpd mpc toggle
Tones and I - Dance Monkey
[paused]  #1/1   1:29/4:11 (35%)
volume: 44%   repeat: off   random: off   single: off   consume: on
[Sun May 12] root@batopi: ~$
jcorporation commented 6 months ago

As a workaround you can change the connection from socket to IP for myMPD. I have no idea why the socket disappears. It must be DietPi or MPD related.

I suspect a mpc -h /var/run/mpd/socket does also not work when the issue appears?

MichaIng commented 6 months ago

The journalctl -u mpd is not complete, is it? systemctl status mpd shows logs, including a (re)start nearly an hour later. Can you check the logs from around this restart?

Generally, the bind_to_address settings (can be defined multiple times) in /etc/mpd.conf define the IP addresses and sockets it listens on. Please check whether the socket is defined there:

grep bind_to_address /etc/mpd.conf

If it is defined, but the socket is missing, there must be some related error in the logs, either at (service) start or e.g. before a(n automatic) restart after a some crash.

jalsco commented 6 months ago

I suspect a mpc -h /var/run/mpd/socket does also not work when the issue appears?

I think No 🤷🏻‍♂️ it does seem to work. That surprises me too.

I mean: when the problem happens, and the ls command finds no socket the MPC client still works, even when used with -h /var/run/mpd/socket. As below 👇

[Mon May 13] root@batopi: ~$ sudo -u mpd mpc -h /var/run/mpd/socket play
Angeline Quinto - At ang Hirap
[playing] #1/28   0:00/4:12 (0%)
volume: 44%   repeat: off   random: off   single: off   consume: on
[Mon May 13] root@batopi: ~$ ls -l /var/run/mpd/socket
ls: cannot access '/var/run/mpd/socket': No such file or directory
[Mon May 13] root@batopi: ~$
MichaIng commented 6 months ago

Just in case, the actual location does not exist either, does it?

ls -l /run/mpd/socket

/var/run is just a symlink to /run since years on any modern distro 😉.

jalsco commented 6 months ago

The journalctl -u mpd is not complete, is it? systemctl status mpd shows logs, including a (re)start nearly an hour later. Can you check the logs from around this restart?

Generally, the bind_to_address settings (can be defined multiple times) in /etc/mpd.conf define the IP addresses and sockets it listens on. Please check whether the socket is defined there:

grep bind_to_address /etc/mpd.conf

If it is defined, but the socket is missing, there must be some related error in the logs, either at (service) start or e.g. before a(n automatic) restart after a some crash.

Hi @MichaIng 😊

A system restart ALWAYS fixes the problem.

At this point in time I have found no other way to fix the problem. Restarting MPD and/or myMPD - does not re-establish the socket.

After a system reboot, the socket will be there, and so myMPD will run, for several hours. Then, often after a period (hours) when no music playing, come back to myMPD to load another playlist and will find this error and that the socket no longer exists: 

root@batopi: ~$ ls -l /var/run/mpd/socket
ls: cannot access '/var/run/mpd/socket': No such file or directory
jalsco commented 6 months ago 
[Mon May 13] root@batopi: ~$ ls -l /run/mpd/socket
ls: cannot access '/run/mpd/socket': No such file or directory
[Mon May 13] root@batopi: ~$
MichaIng commented 6 months ago

The journalctl -u mpd is not complete, is it? systemctl status mpd shows logs, including a (re)start nearly an hour later. Can you check the logs from around this restart? ... If it is defined, but the socket is missing, there must be some related error in the logs, either at (service) start or e.g. before a(n automatic) restart after a some crash.

mpc is probably clever enough to just connect to localhost:6600 if the socket does not exist 🤔. Does the dir still exist?

ls -l /run/mpd

Probably something is wiping /run for some reason.

jalsco commented 6 months ago

Right now, some songs playing by MPC, but the socket does not exist.

[Mon May 13] root@batopi: ~$ systemctl status mpd
● mpd.service - Music Player Daemon
     Loaded: loaded (/lib/systemd/system/mpd.service; enabled; vendor preset: enabled)
    Drop-In: /etc/systemd/system/mpd.service.d
             └─dietpi.conf
     Active: active (running) since Mon 2024-05-13 02:36:14 EDT; 16h ago
TriggeredBy: ● mpd.socket
       Docs: man:mpd(1)
             man:mpd.conf(5)
             file:///usr/share/doc/mpd/html/user.html
   Main PID: 6878 (mpd)
      Tasks: 6 (limit: 2123)
     Memory: 39.3M
        CPU: 1min 25.579s
     CGroup: /system.slice/mpd.service
             └─6878 /usr/bin/mpd --no-daemon

May 13 18:59:05 batopi mpd[6878]: playlist: queue song 1:"Ira/093 U2 - I Still Haven't Found What I'm Looking For.mp3"
May 13 19:01:05 batopi mpd[6878]: state_file: Saving state file /mnt/dietpi_userdata/.mpd_cache/state
May 13 19:03:42 batopi mpd[6878]: decoder_thread: probing plugin mad
May 13 19:03:42 batopi mpd[6878]: decoder: audio_format=44100:24:2, seekable=true
May 13 19:03:42 batopi mpd[6878]: decoder: converting to 64000:32:2
May 13 19:03:42 batopi mpd[6878]: soxr: soxr engine 'cr64'
May 13 19:03:42 batopi mpd[6878]: soxr: soxr precision=28, phase_response=50.00, passband_end=0.91, stopband_begin=1.00
May 13 19:03:42 batopi mpd[6878]: soxr: samplerate conversion ratio to 1.45
May 13 19:03:50 batopi mpd[6878]: player: played "Ira/ikaw.mp3"
May 13 19:03:50 batopi mpd[6878]: playlist: queue song 1:"Ira/The Weeknd - Blinding Lights.mp3"
[Mon May 13] root@batopi: ~$

I will soon do a system reboot , so myMPD works again .

You want some logs from immediately after the reboot ??

jalsco commented 6 months ago 
[Mon May 13] root@batopi: ~$ grep bind_to_address /etc/mpd.conf
bind_to_address                 "localhost"
bind_to_address "/run/mpd/socket"
#       bind_to_address "0.0.0.0"               # optional, IPv4 or IPv6
[Mon May 13] root@batopi: ~$
MichaIng commented 6 months ago

Please check the full service logs for for any restart, crash or error message:

journalctl -u mpd

Use spacebar to scroll them til the bottom.

MichaIng commented 6 months ago

Ah, the socket is not generated by MPD itself, but a dedicated systemd unit:

systemctl status mpd.socket

In case:

journalctl -u mpd.socket
jalsco commented 6 months ago

The ONLY reason this system has rebooted in last month is to make myMPD work again.

I think the MPD log has recycled since the problem occurred (was probably last night, it is unpredicatble). So seems like no errors in there. When the socket drops out MPD still is happy, the paylist continues to play. Only myMPD doesn't work after that - but MPC does work. 

[Mon May 13] root@batopi: ~$ journalctl -u mpd --no-pager
Journal file /var/log/journal/cb0595162f264c0fb73bbfc15e7e6256/system.journal is truncated, ignoring file.
-- Journal begins at Mon 2024-05-13 17:26:20 EDT, ends at Mon 2024-05-13 19:11:43 EDT. --
May 13 18:42:38 batopi mpd[6878]: client: [0] opened from 127.0.0.1:40120
May 13 18:42:38 batopi mpd[6878]: client: [0] process command "status"
May 13 18:42:38 batopi mpd[6878]: client: [0] command returned 0
May 13 18:42:38 batopi mpd[6878]: client: [0] process command "play"
May 13 18:42:38 batopi mpd[6878]: client: [0] command returned 0
May 13 18:42:38 batopi mpd[6878]: client: [0] process command list
May 13 18:42:38 batopi mpd[6878]: client: process command "status"
May 13 18:42:38 batopi mpd[6878]: client: command returned 0
May 13 18:42:38 batopi mpd[6878]: client: process command "currentsong"
May 13 18:42:38 batopi mpd[6878]: client: command returned 0
May 13 18:42:38 batopi mpd[6878]: client: [0] process command list returned 0
May 13 18:42:38 batopi mpd[6878]: client: [0] closed
May 13 18:43:14 batopi mpd[6878]: client: [1] opened from 127.0.0.1:56936
May 13 18:43:14 batopi mpd[6878]: client: [1] process command list
May 13 18:43:14 batopi mpd[6878]: client: process command "tagtypes "clear""
May 13 18:43:14 batopi mpd[6878]: client: command returned 0
May 13 18:43:14 batopi mpd[6878]: client: process command "tagtypes enable Artist AlbumArtist Title Name Composer Performer"
May 13 18:43:14 batopi mpd[6878]: client: command returned 0
May 13 18:43:14 batopi mpd[6878]: client: process command "playlistinfo"
May 13 18:43:14 batopi mpd[6878]: client: command returned 0
May 13 18:43:14 batopi mpd[6878]: client: [1] process command list returned 0
May 13 18:43:14 batopi mpd[6878]: client: [1] closed
May 13 18:47:08 batopi mpd[6878]: client: [2] opened from 127.0.0.1:43796
May 13 18:47:08 batopi mpd[6878]: client: [2] process command list
May 13 18:47:08 batopi mpd[6878]: client: process command "status"
May 13 18:47:08 batopi mpd[6878]: client: command returned 0
May 13 18:47:08 batopi mpd[6878]: client: process command "currentsong"
May 13 18:47:08 batopi mpd[6878]: client: command returned 0
May 13 18:47:08 batopi mpd[6878]: client: [2] process command list returned 0
May 13 18:47:08 batopi mpd[6878]: client: [2] closed
May 13 18:47:45 batopi mpd[6878]: client: [3] opened from 127.0.0.1:36340
May 13 18:47:45 batopi mpd[6878]: client: [3] process command "play"
May 13 18:47:45 batopi mpd[6878]: client: [3] command returned 0
May 13 18:47:45 batopi mpd[6878]: client: [3] process command list
May 13 18:47:45 batopi mpd[6878]: client: process command "status"
May 13 18:47:45 batopi mpd[6878]: client: command returned 0
May 13 18:47:45 batopi mpd[6878]: client: process command "currentsong"
May 13 18:47:45 batopi mpd[6878]: client: command returned 0
May 13 18:47:45 batopi mpd[6878]: client: [3] process command list returned 0
May 13 18:47:45 batopi mpd[6878]: client: [3] closed
May 13 18:48:15 batopi mpd[6878]: client: [4] opened from 127.0.0.1:49672
May 13 18:48:15 batopi mpd[6878]: client: [4] process command list
May 13 18:48:15 batopi mpd[6878]: client: process command "status"
May 13 18:48:15 batopi mpd[6878]: client: command returned 0
May 13 18:48:15 batopi mpd[6878]: client: process command "currentsong"
May 13 18:48:15 batopi mpd[6878]: client: command returned 0
May 13 18:48:15 batopi mpd[6878]: client: [4] process command list returned 0
May 13 18:48:15 batopi mpd[6878]: client: [4] closed
May 13 18:49:06 batopi mpd[6878]: client: [5] opened from 127.0.0.1:36774
May 13 18:49:06 batopi mpd[6878]: client: [5] process command list
May 13 18:49:06 batopi mpd[6878]: client: process command "add "Ira""
May 13 18:49:06 batopi mpd[6878]: client: command returned 0
May 13 18:49:06 batopi mpd[6878]: client: [5] process command list returned 0
May 13 18:49:06 batopi mpd[6878]: client: [5] closed
May 13 18:49:23 batopi mpd[6878]: client: [6] opened from 127.0.0.1:55148
May 13 18:49:23 batopi mpd[6878]: client: [6] process command list
May 13 18:49:23 batopi mpd[6878]: client: process command "tagtypes "clear""
May 13 18:49:23 batopi mpd[6878]: client: command returned 0
May 13 18:49:23 batopi mpd[6878]: client: process command "tagtypes enable Artist AlbumArtist Title Name Composer Performer"
May 13 18:49:23 batopi mpd[6878]: client: command returned 0
May 13 18:49:23 batopi mpd[6878]: client: process command "playlistinfo"
May 13 18:49:23 batopi mpd[6878]: client: command returned 0
May 13 18:49:23 batopi mpd[6878]: client: [6] process command list returned 0
May 13 18:49:23 batopi mpd[6878]: client: [6] closed
May 13 18:49:33 batopi mpd[6878]: client: [7] opened from 127.0.0.1:48636
May 13 18:49:33 batopi mpd[6878]: client: [7] process command "play"
May 13 18:49:33 batopi mpd[6878]: playlist: play 0:"Ira/At Ang Hirap - Angeline Quinto.mp3"
May 13 18:49:33 batopi mpd[6878]: client: [7] command returned 0
May 13 18:49:33 batopi mpd[6878]: playlist: queue song 1:"Ira/Sabay Tayo - 420 Soldierz.mp3"
May 13 18:49:33 batopi mpd[6878]: client: [7] process command list
May 13 18:49:33 batopi mpd[6878]: client: process command "status"
May 13 18:49:33 batopi mpd[6878]: client: command returned 0
May 13 18:49:33 batopi mpd[6878]: client: process command "currentsong"
May 13 18:49:33 batopi mpd[6878]: client: command returned 0
May 13 18:49:33 batopi mpd[6878]: client: [7] process command list returned 0
May 13 18:49:33 batopi mpd[6878]: decoder_thread: probing plugin mad
May 13 18:49:33 batopi mpd[6878]: client: [7] closed
May 13 18:49:33 batopi mpd[6878]: decoder: audio_format=44100:24:2, seekable=true
May 13 18:49:33 batopi mpd[6878]: decoder: converting to 64000:32:2
May 13 18:49:33 batopi mpd[6878]: soxr: soxr engine 'cr64'
May 13 18:49:33 batopi mpd[6878]: soxr: soxr precision=28, phase_response=50.00, passband_end=0.91, stopband_begin=1.00
May 13 18:49:33 batopi mpd[6878]: soxr: samplerate conversion ratio to 1.45
May 13 18:49:33 batopi mpd[6878]: alsa_output: opened default type=PLUG
May 13 18:49:33 batopi mpd[6878]: alsa_output: buffer: size=21..87381 time=328..1365329
May 13 18:49:33 batopi mpd[6878]: alsa_output: period: size=10..43691 time=166..682667
May 13 18:49:33 batopi mpd[6878]: alsa_output: default period_time = buffer_time/4 = 500000/4 = 125000
May 13 18:49:33 batopi mpd[6878]: alsa_output: format=S32_LE (Signed 32 bit Little Endian)
May 13 18:49:33 batopi mpd[6878]: alsa_output: buffer_size=32000 period_size=8000
May 13 18:49:33 batopi mpd[6878]: output: opened "DietPi ALSA" (alsa) audio_format=64000:32:2
May 13 18:51:06 batopi mpd[6878]: state_file: Saving state file /mnt/dietpi_userdata/.mpd_cache/state
May 13 18:53:37 batopi mpd[6878]: decoder_thread: probing plugin mad
May 13 18:53:37 batopi mpd[6878]: decoder: audio_format=44100:24:2, seekable=true
May 13 18:53:37 batopi mpd[6878]: decoder: converting to 64000:32:2
May 13 18:53:37 batopi mpd[6878]: soxr: soxr engine 'cr64'
May 13 18:53:37 batopi mpd[6878]: soxr: soxr precision=28, phase_response=50.00, passband_end=0.91, stopband_begin=1.00
May 13 18:53:37 batopi mpd[6878]: soxr: samplerate conversion ratio to 1.45
May 13 18:53:44 batopi mpd[6878]: player: played "Ira/At Ang Hirap - Angeline Quinto.mp3"
May 13 18:53:44 batopi mpd[6878]: playlist: queue song 1:"Ira/ikaw.mp3"
May 13 18:54:43 batopi mpd[6878]: client: [8] opened from 127.0.0.1:60980
May 13 18:54:43 batopi mpd[6878]: client: [8] process command "play"
May 13 18:54:43 batopi mpd[6878]: client: [8] command returned 0
May 13 18:54:43 batopi mpd[6878]: client: [8] process command list
May 13 18:54:43 batopi mpd[6878]: client: process command "status"
May 13 18:54:43 batopi mpd[6878]: client: command returned 0
May 13 18:54:43 batopi mpd[6878]: client: process command "currentsong"
May 13 18:54:43 batopi mpd[6878]: client: command returned 0
May 13 18:54:43 batopi mpd[6878]: client: [8] process command list returned 0
May 13 18:54:43 batopi mpd[6878]: client: [8] closed
May 13 18:55:44 batopi mpd[6878]: state_file: Saving state file /mnt/dietpi_userdata/.mpd_cache/state
May 13 18:58:58 batopi mpd[6878]: decoder_thread: probing plugin mad
May 13 18:58:58 batopi mpd[6878]: mad: detected LAME version 3.99 ("LAME3.99r")
May 13 18:58:58 batopi mpd[6878]: mad: LAME peak found: 0.000000
May 13 18:58:58 batopi mpd[6878]: mad: LAME track gain found: -7.400000
May 13 18:58:58 batopi mpd[6878]: mad: encoder delay is 576, encoder padding is 1596
May 13 18:58:58 batopi mpd[6878]: decoder: audio_format=44100:24:2, seekable=true
May 13 18:58:58 batopi mpd[6878]: decoder: converting to 64000:32:2
May 13 18:58:58 batopi mpd[6878]: soxr: soxr engine 'cr64'
May 13 18:58:58 batopi mpd[6878]: soxr: soxr precision=28, phase_response=50.00, passband_end=0.91, stopband_begin=1.00
May 13 18:58:58 batopi mpd[6878]: soxr: samplerate conversion ratio to 1.45
May 13 18:59:05 batopi mpd[6878]: player: played "Ira/Sabay Tayo - 420 Soldierz.mp3"
May 13 18:59:05 batopi mpd[6878]: playlist: queue song 1:"Ira/093 U2 - I Still Haven't Found What I'm Looking For.mp3"
May 13 19:01:05 batopi mpd[6878]: state_file: Saving state file /mnt/dietpi_userdata/.mpd_cache/state
May 13 19:03:42 batopi mpd[6878]: decoder_thread: probing plugin mad
May 13 19:03:42 batopi mpd[6878]: decoder: audio_format=44100:24:2, seekable=true
May 13 19:03:42 batopi mpd[6878]: decoder: converting to 64000:32:2
May 13 19:03:42 batopi mpd[6878]: soxr: soxr engine 'cr64'
May 13 19:03:42 batopi mpd[6878]: soxr: soxr precision=28, phase_response=50.00, passband_end=0.91, stopband_begin=1.00
May 13 19:03:42 batopi mpd[6878]: soxr: samplerate conversion ratio to 1.45
May 13 19:03:50 batopi mpd[6878]: player: played "Ira/ikaw.mp3"
May 13 19:03:50 batopi mpd[6878]: playlist: queue song 1:"Ira/The Weeknd - Blinding Lights.mp3"
May 13 19:05:50 batopi mpd[6878]: state_file: Saving state file /mnt/dietpi_userdata/.mpd_cache/state
May 13 19:08:24 batopi mpd[6878]: decoder_thread: probing plugin mad
May 13 19:08:24 batopi mpd[6878]: decoder: audio_format=44100:24:2, seekable=true
May 13 19:08:24 batopi mpd[6878]: decoder: converting to 64000:32:2
May 13 19:08:24 batopi mpd[6878]: soxr: soxr engine 'cr64'
May 13 19:08:24 batopi mpd[6878]: soxr: soxr precision=28, phase_response=50.00, passband_end=0.91, stopband_begin=1.00
May 13 19:08:24 batopi mpd[6878]: soxr: samplerate conversion ratio to 1.45
May 13 19:08:30 batopi mpd[6878]: player: played "Ira/093 U2 - I Still Haven't Found What I'm Looking For.mp3"
May 13 19:08:30 batopi mpd[6878]: playlist: queue song 1:"Ira/Arash feat.Helena - Broken Angel.mp3"
May 13 19:10:30 batopi mpd[6878]: state_file: Saving state file /mnt/dietpi_userdata/.mpd_cache/state
[Mon May 13] root@batopi: ~$
jalsco commented 6 months ago 
[Mon May 13] root@batopi: ~$ systemctl status mpd.socket
● mpd.socket
     Loaded: loaded (/lib/systemd/system/mpd.socket; enabled; vendor preset: enabled)
     Active: active (running) since Sun 2024-05-12 20:53:47 EDT; 22h ago
   Triggers: ● mpd.service
     Listen: /run/mpd/socket (Stream)
             [::]:6600 (Stream)
      Tasks: 0 (limit: 2123)
     Memory: 4.0K
        CPU: 2ms
     CGroup: /system.slice/mpd.socket

Warning: journal has been rotated since unit was started, output may be incomplete.
[Mon May 13] root@batopi: ~$ journalctl -u mpd.socket
Journal file /var/log/journal/cb0595162f264c0fb73bbfc15e7e6256/system.journal is truncated, ignoring file.
-- Journal begins at Mon 2024-05-13 17:26:20 EDT, ends at Mon 2024-05-13 19:16:18 EDT. --
-- No entries --
[Mon May 13] root@batopi: ~$ ls -l /run/mpd/socket
ls: cannot access '/run/mpd/socket': No such file or directory
[Mon May 13] root@batopi: ~$
jalsco commented 6 months ago

Some lines from an earlier log, in an earlier post in this thread : 

May 12 21:58:46 batopi mpd[3510]: state_file: Loading state file /mnt/dietpi_userdata/.mpd_cache/state
May 12 21:58:46 batopi mpd[3510]: inotify: initializing inotify
May 12 21:58:46 batopi mpd[3510]: exception: U_INVALID_CHAR_FOUND
May 12 21:58:46 batopi mpd[3510]: inotify: watching music directory
May 12 21:58:46 batopi systemd[1]: Started Music Player Daemon.

Can that that exception ☝ be part of the problem ?

MichaIng commented 6 months ago

Does restarting that socket unit fix it?

systemctl restart mpd.socket

Since logs were truncated, check them again (for the socket unit) once you face the issue.

The inotify error is unrelated. This is a kernel feature to monitor file changes in a directory, used here to check for changes in the music directory. Probably one of the files has an invalid character for this.

jalsco commented 6 months ago 
[Mon May 13] root@batopi: ~$ systemctl restart mpd.socket
Job failed. See "journalctl -xe" for details.
[Mon May 13] root@batopi: ~$ journalctl -u mpd.socket --no-pager
Journal file /var/log/journal/cb0595162f264c0fb73bbfc15e7e6256/system.journal is truncated, ignoring file.
-- Journal begins at Mon 2024-05-13 17:56:30 EDT, ends at Mon 2024-05-13 19:44:13 EDT. --
May 13 19:42:39 batopi systemd[1]: mpd.socket: Succeeded.
May 13 19:42:39 batopi systemd[1]: Closed mpd.socket.
May 13 19:42:39 batopi systemd[1]: Stopping mpd.socket.
May 13 19:42:39 batopi systemd[1]: mpd.socket: Socket service mpd.service already active, refusing.
May 13 19:42:39 batopi systemd[1]: Failed to listen on mpd.socket.
[Mon May 13] root@batopi: ~$ ls -l /run/mpd/socket
ls: cannot access '/run/mpd/socket': No such file or directory
[Mon May 13] root@batopi: ~$
MichaIng commented 6 months ago

Hmm, I guess it is an activation socket as well, but still strange that it refuses to start just because its activation service is running already. Please try it like that:

systemctl stop mpd
systemctl restart mpd.socket
systemctl start mpd
jalsco commented 6 months ago

Since logs were truncated, check them again (for the socket unit) once you face the issue.

Ok. As the socket don't exist now, and only way we know to re-establish it is a system reboot, planning to do restart in next 30mins. As mentioned, the system has been restarted 10-15 times in last month, each restart was done only to make myMPD work again... IF not for this problem, then would have been no restarts.

As soon as we detect the problem has happened, I will get the MPD logs.

In order to do that I will tell the others "no long play lists, 3 or 4 songs max" . Because, when a long playlist (6+ hours) is loaded the socket can drop out any time and we wouldn't know about it because the music keeps playing.

jalsco commented 6 months ago 
[Mon May 13] root@batopi: ~$ systemctl stop mpd
Warning: Stopping mpd.service, but it can still be activated by:
  mpd.socket
[Mon May 13] root@batopi: ~$ systemctl restart mpd.socket
Job failed. See "journalctl -xe" for details.
[Mon May 13] root@batopi: ~$ journalctl -u mpd.socket --no-pager
Journal file /var/log/journal/cb0595162f264c0fb73bbfc15e7e6256/system.journal is truncated, ignoring file.
-- Journal begins at Mon 2024-05-13 18:10:57 EDT, ends at Mon 2024-05-13 19:57:37 EDT. --
May 13 19:42:39 batopi systemd[1]: mpd.socket: Succeeded.
May 13 19:42:39 batopi systemd[1]: Closed mpd.socket.
May 13 19:42:39 batopi systemd[1]: Stopping mpd.socket.
May 13 19:42:39 batopi systemd[1]: mpd.socket: Socket service mpd.service already active, refusing.
May 13 19:42:39 batopi systemd[1]: Failed to listen on mpd.socket.
May 13 19:56:15 batopi systemd[1]: Listening on mpd.socket.
May 13 19:57:07 batopi systemd[1]: mpd.socket: Succeeded.
May 13 19:57:07 batopi systemd[1]: Closed mpd.socket.
May 13 19:57:07 batopi systemd[1]: Stopping mpd.socket.
May 13 19:57:07 batopi systemd[1]: mpd.socket: Socket service mpd.service already active, refusing.
May 13 19:57:07 batopi systemd[1]: Failed to listen on mpd.socket.
[Mon May 13] root@batopi: ~$
MichaIng commented 6 months ago 
May 13 19:42:39 batopi systemd[1]: Failed to listen on mpd.socket.
May 13 19:56:15 batopi systemd[1]: Listening on mpd.socket.
May 13 19:57:07 batopi systemd[1]: mpd.socket: Succeeded.
May 13 19:57:07 batopi systemd[1]: Closed mpd.socket.
May 13 19:57:07 batopi systemd[1]: Stopping mpd.socket.
May 13 19:57:07 batopi systemd[1]: mpd.socket: Socket service mpd.service already active, refusing.
May 13 19:57:07 batopi systemd[1]: Failed to listen on mpd.socket.

Ah, seeing the 2nd log entry, I guess it is systemd failing to listen on the socket, since MPD is listening on it already. So as long as MPD does not run yet, systemd listens on the socket, using it as activation socket. I.e. local MPD clients who try to connect through the socket will trigger the MPD start (the same even works for 6600 TCP port). But once MPD was started, of course it must listen on the socket instead, so systemd cannot do that anymore. But once you stop MPD, systemd automatically starts to listen on it again, as activation socket. This is what happened at 19:56:15, which is when you stopped MPD, I guess. However, "Listening on mpd.socket" does not make sense if the socket file does not exist. Is it still missing now or finally created? And if not, does the runtime dir at least exist?

ls -l /run/mpd
jalsco commented 6 months ago 
[Mon May 13] root@batopi: ~$ ls -l /run/mpd
total 0
[Mon May 13] root@batopi: ~$
MichaIng commented 6 months ago

Confusing. Please try to reinstall MPD, maybe there is something broken:

apt install --reinstall mpd
jalsco commented 6 months ago 
[Mon May 13] root@batopi: ~$ apt install --reinstall mpd
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
0 upgraded, 0 newly installed, 1 reinstalled, 0 to remove and 0 not upgraded.
Need to get 693 kB of archives.
After this operation, 0 B of additional disk space will be used.
Get:1 https://deb.debian.org/debian bullseye/main arm64 mpd arm64 0.22.6-1+b1 [693 kB]
Fetched 693 kB in 3s (231 kB/s)
(Reading database ... 57886 files and directories currently installed.)
Preparing to unpack .../mpd_0.22.6-1+b1_arm64.deb ...
Unpacking mpd (0.22.6-1+b1) over (0.22.6-1+b1) ...
Setting up mpd (0.22.6-1+b1) ...
Processing triggers for man-db (2.9.4-2) ...
Processing triggers for hicolor-icon-theme (0.17-2) ...
[Mon May 13] root@batopi: ~$ ls -l /run/mpd
total 0
srw-rw-rw- 1 mpd audio 0 May 13 20:11 socket
[Mon May 13] root@batopi: ~$ ls -l /run/mpd/socket
srw-rw-rw- 1 mpd audio 0 May 13 20:11 /run/mpd/socket
[Mon May 13] root@batopi: ~$

ok - working now. Same as like a restart. I will report back if/when it stops running ... usually takes many hours

jalsco commented 6 months ago

The problem is back 😥 There was an upgrade to myMPD 👇, applied, and then... the socket doesn't exist. 

[Tue May 14] root@batopi: ~$ apt upgrade
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
Calculating upgrade... Done
The following packages will be upgraded:
  mympd
1 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
Need to get 800 kB of archives.
After this operation, 4096 B disk space will be freed.
Do you want to continue? [Y/n] Y
Get:1 https://ftp.lysator.liu.se/pub/opensuse/repositories/home%3A/jcorporation/Debian_11  mympd 15.0.2-1 [800 kB]
Fetched 800 kB in 12s (65.9 kB/s)
(Reading database ... 57886 files and directories currently installed.)
Preparing to unpack .../mympd_15.0.2-1_arm64.deb ...
Unpacking mympd (15.0.2-1) over (15.0.1-1) ...
Setting up mympd (15.0.2-1) ...
Warning: The unit file, source configuration file or drop-ins of mympd.service changed on disk. Run 'systemctl daemon-reload' to reload units.
Removing obsolet mympd user and group
Processing triggers for man-db (2.9.4-2) ...
[Tue May 14] root@batopi: ~$ systemctl daemon-reload
[Wed May 15] root@batopi: ~$ ls -l /run/mpd/socket
ls: cannot access '/run/mpd/socket': No such file or directory
[Wed May 15] root@batopi: ~$

So each time myMPD changes I need to do apt install --reinstall mpd to make it work again ?

jcorporation commented 5 months ago

myMPD itself does not touch the MPD socket while installing. Upgrading myMPD could not be the root cause of your problem.

jalsco commented 5 months ago 
Warning: The unit file, source configuration file or drop-ins of mympd.service changed on disk. Run 'systemctl daemon-reload' to reload units.
Removing obsolet mympd user and group

I think it was this step ☝ that may have caused the problems. The myMPD user before was "mpd". Removing it seems like a big step. It just did all that automatically.

Anyway - all that is unrelated. Because now is the next morning here. And, after non use of music overnight, SAME problem confronts me now. That is the socket doesn't exist and therefore myMPD wont work again 😥

Thanks to @MichaIng and his comment earlier in this thread - I will now just do yet another apt install --reinstall mpd and presto it works again.

That is FAR better than doing a system reboot each time. BUT it is hardly desirable to be doing apt install --reinstall mpd a couple of times every day, and certainly every morning, just to get around the fact that the mpd socket drops out....

As a workaround, this is an improvement over sudo reboot now, but I am still hopeful that the actual problem can be fixed in the future. I think we know more now, but the exact explanation of why the socket drops out is not known yet.

jcorporation commented 5 months ago

It seems to be more a DietPi issue or an issue with you individual setup than a myMPD issue. Have you tried to reconfigure myMPD to connect to MPD by IP? Host localhost and port 6600 are the defaults. You can set this in the Connection dialog in myMPD. This does not fix the root cause but it could by a valid workaround for you.

MichaIng commented 5 months ago

The (obsolete) "mympd" user is unrelated to the "mpd" socket. The warning about changed unit files during APT package upgrades is as well pretty common an unrelated, though could be muted with a systemctl daemon-reload within postinst, before touching the service. If I am not mistaken, the code blocks added by debhelper automatically, deal with this as well.

However, not a myMPD issue for sure. Not a (general) DietPi issue either. But we need to find out what removes the socket why.

Of course a package upgrade might be indirectly causing this, or also the systemd reload:

ls -l /run/mpd/socket
systemctl daemon-reload
ls -l /run/mpd/socket
apt install --reinstall mympd
ls -l /run/mpd/socket

If the socket is missing after one step, check logs again:

journalctl -e -u mpd -u mpd.socket

-e to jump to the end.

If not, maybe setup some loop check regularly check for the socket and store a timestamp once it is missing? So we check see journalctl and dmesg about what happened right at that time? I am wondering how to effectively monitor what is touching a file. fuser /run/mpd/sockiet shows what is currently accessing the socket, so we'd miss a one-time removal. Maybe inotify:

apt install inotify-tools
inotifywatch /run/mpd/sockiet

Probably requires some CLI options, I'll have a look tonight: https://manpages.debian.org/inotifywatch