bug#44820: MPD fails after respawning too often

bug#44820: MPD fails after respawning too often

[Simon]

On a recent pull, MPD will not start any more.

Herd status reports:
--8<---------------cut here---------------start------------->8---
Status of mpd:
  It is stopped.
  It is disabled.
  Provides (mpd).
  Requires (user-processes).
  Conflicts with ().
  Will be respawned.
  Last respawned on Mon Nov 23 10:22:07+0100 2020.
--8<---------------cut here---------------end--------------->8---

Reading my messages, I find:
--8<---------------cut here---------------start------------->8---
Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been disabled.
Nov 23 10:22:07 localhost shepherd[1]:   (Respawning too fast.)
--8<---------------cut here---------------end--------------->8---

Unfortunately, there are no further messages as to why the service is
disabled, or why the daemon is respawning too often.

If I manually call the daemon with `$ ./mpd --no-daemon --stdout
--verbose' from the store, I get:
--8<---------------cut here---------------start------------->8---
config_file: loading file /home/user/.config/mpd/mpd.conf
libsamplerate: libsamplerate converter 'Fastest Sinc Interpolator'
vorbis: Xiph.Org libVorbis 1.3.6
opus: libopus 1.3.1
sndfile: libsndfile-1.0.30
hybrid_dsd: The Hybrid DSD decoder is disabled because it was not explicitly enabled
simple_db: reading DB
curl: version 7.71.0
curl: with GnuTLS/3.6.14
state_file: Loading state file /home/user/.mpd/state
exception: RTIOThread could not get realtime scheduling, continuing anyway: sched_setscheduler failed: Operation not permitted
playlist: queue song 7:"Can/CAN/08 Can Be.mp3"
decoder_thread: probing plugin ffmpeg
exception: OutputThread could not get realtime scheduling, continuing anyway: sched_setscheduler failed: Operation not permitted
ffmpeg/mp3: Format mp3 probed with size=65536 and score=51
ffmpeg/mp3: pad 576 1788
ffmpeg/mp3: Skipping 0 bytes of junk at 37617.
ffmpeg: detected input format 'mp3' (MP2/3 (MPEG audio layer 2/3))
ffmpeg/mp3: Before avformat_find_stream_info() pos: 37617 bytes read:65536 seeks:0 nb_streams:2
ffmpeg/mjpeg: marker=d8 avail_size_in_buf=34312
ffmpeg/mjpeg: marker parser used 0 bytes (0 bits)
ffmpeg/mjpeg: marker=e0 avail_size_in_buf=34310
ffmpeg/mjpeg: marker parser used 16 bytes (128 bits)
ffmpeg/mjpeg: marker=db avail_size_in_buf=34292
ffmpeg/mjpeg: index=0
ffmpeg/mjpeg: qscale[0]: 2
ffmpeg/mjpeg: marker parser used 67 bytes (536 bits)
ffmpeg/mjpeg: marker=db avail_size_in_buf=34223
ffmpeg/mjpeg: index=1
ffmpeg/mjpeg: qscale[1]: 5
ffmpeg/mjpeg: marker parser used 67 bytes (536 bits)
ffmpeg/mjpeg: marker=c0 avail_size_in_buf=34154
ffmpeg/mjpeg: Changing bps from 0 to 8
ffmpeg/mjpeg: sof0: picture: 622x622
ffmpeg/mjpeg: component 0 2:2 id: 0 quant:0
ffmpeg/mjpeg: component 1 1:1 id: 1 quant:1
ffmpeg/mjpeg: component 2 1:1 id: 2 quant:1
ffmpeg/mjpeg: pix fmt id 22111100
ffmpeg/mjpeg: Format yuvj420p chosen by get_format().
ffmpeg/mjpeg: marker parser used 17 bytes (136 bits)
ffmpeg/mjpeg: marker=c4 avail_size_in_buf=34135
ffmpeg/mjpeg: marker parser used 0 bytes (0 bits)
ffmpeg/mjpeg: marker=c4 avail_size_in_buf=34102
ffmpeg/mjpeg: marker parser used 0 bytes (0 bits)
ffmpeg/mjpeg: marker=c4 avail_size_in_buf=33919
ffmpeg/mjpeg: marker parser used 0 bytes (0 bits)
ffmpeg/mjpeg: marker=c4 avail_size_in_buf=33886
ffmpeg/mjpeg: marker parser used 0 bytes (0 bits)
ffmpeg/mjpeg: escaping removed 102 bytes
ffmpeg/mjpeg: marker=da avail_size_in_buf=33703
ffmpeg/mjpeg: marker parser used 33601 bytes (268808 bits)
ffmpeg/mjpeg: marker=d9 avail_size_in_buf=0
ffmpeg/mjpeg: decode frame unused 0 bytes
ffmpeg/mp3: demuxer injecting skip 1105 / discard 0
ffmpeg/mp3float: skip 1105 / discard 0 samples due to side data
ffmpeg/mp3float: skip 1105/1152 samples
ffmpeg/mp3: All info found
ffmpeg/mp3: stream 0: start_time: 0.0250567 duration: 22.3869
ffmpeg/mp3: stream 1: start_time: 0.0250556 duration: 22.3869
ffmpeg/mp3: format: start_time: 0.025056 duration: 22.3869 (estimate from stream) bitrate=333 kb/s
ffmpeg/mp3: After avformat_find_stream_info() pos: 90865 bytes read:98304 seeks:0 frames:51
ffmpeg: codec 'mp3'
decoder: audio_format=44100:f:2, seekable=true
ffmpeg/mp3: demuxer injecting skip 1105 / discard 0
client: [0] opened from 127.0.0.1:40210
client: [0] process command "status"
client: [0] command returned 0
client: [0] process command "plchanges "0""
client: [0] command returned 0
client: [0] process command "decoders"
client: [0] command returned 0
client: [0] process command "idle"
client: [0] command returned 1
^Cstate_file: Saving state file /home/user/.mpd/state
player: played "Can/CAN/07 Ping Pong.mp3"
fifo_output: Removing FIFO "/tmp/mpd.fifo"
--8<---------------cut here---------------end--------------->8---

Hence the daemon will run it manually from the store, but there are no
hints as to why it fails at boot time.

Any help is appreciated.


Cheers,
Simon

bug#44820: MPD fails after respawning too often

[Ludovic Courtès]

Hi,

Simon <lists@netpanic.org> skribis:

> On a recent pull, MPD will not start any more.
>
> Herd status reports:
>
> Status of mpd:
>   It is stopped.
>   It is disabled.
>   Provides (mpd).
>   Requires (user-processes).
>   Conflicts with ().
>   Will be respawned.
>   Last respawned on Mon Nov 23 10:22:07+0100 2020.
>
>
> Reading my messages, I find:
>
> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been disabled.
> Nov 23 10:22:07 localhost shepherd[1]:   (Respawning too fast.)
>
>
> Unfortunately, there are no further messages as to why the service is
> disabled, or why the daemon is respawning too often.

Does /var/log/mpd/mpd.log or similar contain useful info?

Could you share your ‘mpd-configuration’?

There have been two changes recently, which fixed the mpd system test,
but perhaps they introduced other issues:

  https://git.savannah.gnu.org/cgit/guix.git/log?id=bb124f6e9c0af0a23736f233c2ea2c9c9b4a40a6

Thanks for reporting the issue,
Ludo’.

bug#44820: MPD fails after respawning too often

[Martin Becze]

I also ran into this problem. Here is the relevnat part of 
/var/run/mpd/<mpd-user>/log

> exception: Failed to create pid file "/var/run/mpd/<mpd-user>/pid": Permission denied

A quick dirty fix is just to chown the /var/run/mpd folder so that mpd 
can create its pid file.

On 11/27/20 4:31 AM, Ludovic Courtès wrote:
> Hi,
> 
> Simon <lists@netpanic.org> skribis:
> 
>> On a recent pull, MPD will not start any more.
>>
>> Herd status reports:
>>
>> Status of mpd:
>>    It is stopped.
>>    It is disabled.
>>    Provides (mpd).
>>    Requires (user-processes).
>>    Conflicts with ().
>>    Will be respawned.
>>    Last respawned on Mon Nov 23 10:22:07+0100 2020.
>>
>>
>> Reading my messages, I find:
>>
>> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
>> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
>> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
>> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
>> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
>> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been disabled.
>> Nov 23 10:22:07 localhost shepherd[1]:   (Respawning too fast.)
>>
>>
>> Unfortunately, there are no further messages as to why the service is
>> disabled, or why the daemon is respawning too often.
> 
> Does /var/log/mpd/mpd.log or similar contain useful info?
> 
> Could you share your ‘mpd-configuration’?
> 
> There have been two changes recently, which fixed the mpd system test,
> but perhaps they introduced other issues:
> 
>    https://git.savannah.gnu.org/cgit/guix.git/log?id=bb124f6e9c0af0a23736f233c2ea2c9c9b4a40a6
> 
> Thanks for reporting the issue,
> Ludo’.
> 
> 
> 

bug#44820: MPD fails after respawning too often

[Simon Streit]

Martin Becze writes:

> I also ran into this problem. Here is the relevnat part of
> /var/run/mpd/<mpd-user>/log
>
>> exception: Failed to create pid file "/var/run/mpd/<mpd-user>/pid": Permission denied
>
> A quick dirty fix is just to chown the /var/run/mpd folder so that mpd
> can create its pid file.

I have the the same error message in my log file too, and chowning
ownership of directories helps too.



>
> On 11/27/20 4:31 AM, Ludovic Courtès wrote:
>> Hi,
>> Simon <lists@netpanic.org> skribis:
>>
>>> On a recent pull, MPD will not start any more.
>>>
>>> Herd status reports:
>>>
>>> Status of mpd:
>>>    It is stopped.
>>>    It is disabled.
>>>    Provides (mpd).
>>>    Requires (user-processes).
>>>    Conflicts with ().
>>>    Will be respawned.
>>>    Last respawned on Mon Nov 23 10:22:07+0100 2020.
>>>
>>>
>>> Reading my messages, I find:
>>>
>>> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
>>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
>>> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
>>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
>>> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
>>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
>>> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
>>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
>>> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
>>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
>>> Nov 23 10:22:07 localhost shepherd[1]: Respawning mpd.
>>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been started.
>>> Nov 23 10:22:07 localhost shepherd[1]: Service mpd has been disabled.
>>> Nov 23 10:22:07 localhost shepherd[1]:   (Respawning too fast.)
>>>
>>>
>>> Unfortunately, there are no further messages as to why the service is
>>> disabled, or why the daemon is respawning too often.
>> Does /var/log/mpd/mpd.log or similar contain useful info?
>> Could you share your ‘mpd-configuration’?
>> There have been two changes recently, which fixed the mpd system
>> test,
>> but perhaps they introduced other issues:
>>    https://git.savannah.gnu.org/cgit/guix.git/log?id=bb124f6e9c0af0a23736f233c2ea2c9c9b4a40a6
>> Thanks for reporting the issue,
>> Ludo’.


If I read it correctly in the changes made above, ownership of the
directory should be changed, but it is not.  I just deleted the
directory in /run/mpd and did a reboot.  The user directory is
recreated, and .mpd too, but only ownership is changed in .mpd.

Too bad that my knowledge in guile is too limited at the moment to
provide a solution.  But I'd really love too at the moment. :)

But I believe ownership of the parent directory should be changed
according to the user.

Sorry that I can't provide any better solution at the moment.


Cheers,
Simon

bug#44820: MPD fails after respawning too often

[Ludovic Courtès]

Hi Martin,

Martin Becze <mjbecze@riseup.net> skribis:

> I also ran into this problem. Here is the relevnat part of
> /var/run/mpd/<mpd-user>/log
>
>> exception: Failed to create pid file "/var/run/mpd/<mpd-user>/pid": Permission denied
>
> A quick dirty fix is just to chown the /var/run/mpd folder so that mpd
> can create its pid file.

So was the ownership of /var/run/mpd/$USER wrong?

Thanks,
Ludo’.

bug#44820: MPD fails after respawning too often

[Simon Streit]

Ludovic Courtès writes:

> Hi Martin,
>
> Martin Becze <mjbecze@riseup.net> skribis:
>
>> I also ran into this problem. Here is the relevnat part of
>> /var/run/mpd/<mpd-user>/log
>>
>>> exception: Failed to create pid file "/var/run/mpd/<mpd-user>/pid": Permission denied
>>
>> A quick dirty fix is just to chown the /var/run/mpd folder so that mpd
>> can create its pid file.
>
> So was the ownership of /var/run/mpd/$USER wrong?

`/var/run/mpd' and subsequent user folders belong to root:root.  Only
`/var/run/mpd/mpd' belong to mpd:mpd.  They where recreated belonging to
root:root after deleting them.

>
> Thanks,
> Ludo’.

bug#44820: MPD fails after respawning too often

[Martin Becze]

Yeah, owner gets set to root when it should be mpd-user.

On 12/3/20 11:05 AM, Ludovic Courtès wrote:
> So was the ownership of/var/run/mpd/$USER wrong?

bug#44820: MPD fails after respawning too often

[Ludovic Courtès]

Hi!

I believe this is fixed by ce3b5e5a8d8566162201cb778c4586f94a626dfa.

Thanks,
Ludo’.