search

PromyLOPh / pianobar

Console-based pandora.com player
http://6xq.net/pianobar/
Other
1.74k stars 321 forks source link

Unable to pause and resume playback #672

Closed basicide closed 5 years ago

basicide commented 5 years ago

Subject of the issue

When I pause the player for any amount of time and try to resume playback (usually within 60 seconds), the stream fails to continue playing the current song and skips to the next song

Your environment

pianobar 2018.06.22 MacOS 10.12.6 ffmpeg - stable 4.0.2, libav - stable 12.3

config

user = USER@NAME password = PASS autostart_station = #### history = 10 audio_quality = high max_retry = 5 timeout = 300 format_nowplaying_song = %t by %a on %l%r%@%s format_nowplaying_station = Station %n format_list_song = %i) %a - %t%r

Steps to reproduce

Play a song on any station, pause the song for about 10-15 seconds, resume song

Expected behaviour

Song should continue playing as normal.

Actual behaviour

Song plays for ~10 seconds, then skips to next song

PromyLOPh commented 5 years ago

Do you know whether pianobar is linked against ffmpeg or libav?

basicide commented 5 years ago

I'm not sure. How would I check?

haarp commented 5 years ago

I'm experiencing a similar bug.

pianobar 2018.06.22 Linux ffmpeg 3.3.6

When I paus playback for longer than a minute or so, then resume, pianobar will continue playing for a few seconds and then get stuck. Sometimes I can get it going again by issuing Ctrl+C, sometimes I have to skip to the next song.

It seems pianobar is only downloading and playing back small chunks of a song, which results in timeouts when pausing too long. Wouldn't it be sensible to simply cache the entire song in memory?

PromyLOPh commented 5 years ago

@basicide You can run ldd pianobar and then check which libav* it is linked against.

@haarp No, it increases memory usage and spikes network bandwidth usage for no good reason.

Can you check if the problem exists with the latest development snapshot as well? There has been a major change since 2018.06.22

basicide commented 5 years ago

I'm on MacOS, but here's the closest I could get to 'ldd pianobar'.

/usr/local/bin/pianobar: /usr/lib/libSystem.B.dylib (compatibility version 1.0.0, current version 1252.200.5) /usr/local/opt/ffmpeg/lib/libavcodec.58.dylib (compatibility version 58.0.0, current version 58.18.100) /usr/local/opt/ffmpeg/lib/libavformat.58.dylib (compatibility version 58.0.0, current version 58.12.100) /usr/local/opt/ffmpeg/lib/libavutil.56.dylib (compatibility version 56.0.0, current version 56.14.100) /usr/local/opt/ffmpeg/lib/libavfilter.7.dylib (compatibility version 7.0.0, current version 7.16.100) /usr/lib/libcurl.4.dylib (compatibility version 7.0.0, current version 9.0.0) /usr/local/opt/libgcrypt/lib/libgcrypt.20.dylib (compatibility version 23.0.0, current version 23.3.0) /usr/local/opt/json-c/lib/libjson-c.4.dylib (compatibility version 5.0.0, current version 5.0.0) /usr/local/opt/libao/lib/libao.4.dylib (compatibility version 6.0.0, current version 6.1.0)

I haven't updated to the latest snapshot, but I can try that later and report back.

haarp commented 5 years ago

No, it increases memory usage and spikes network bandwidth usage for no good reason.

Such a spike occurs whenever any software downloads anything. It's a very common occurence and nothing that needs to be avoided. Memory usage might be an issue on limited mobile devices, true, but a desktop machine won't care about a few more MB.

A config setting that enables caching the entire track would be a good idea imo. But that's independent from this bug here.

Can you check if the problem exists with the latest development snapshot as well? There has been a major change since 2018.06.22

No difference. After a longer pause followed by a resume, there's roughly 15 seconds of music left before it stops. Sometimes it then starts again after a while, most of the time I have to manually intervene.

If I wait really long, Pandora even denies me access to the tracks in the current playlist (403). pianobar then cycles through the remaining playlist tracks, encounters 403 on all of them, then stops working altogether (instead of simply getting a new playlist)

basicide commented 5 years ago

The dev version doesn't appear to work for me at all. It plays for 5 seconds then becomes totally unresponsive. The song timer doesn't tick either.

PromyLOPh commented 5 years ago

A config setting that enables caching the entire track would be a good idea imo. But that's independent from this bug here. Prior to commit bbbdd99fdaacfe0a3c9a1237fa0d086907c1286f there was no cache at all (and thus no switch to turn it on). Now a buffer for decoded audio exists, but its size is currently hard-coded: https://github.com/PromyLOPh/pianobar/blob/master/src/player.c#L437 You can try and play with it, but it won’t solve this problem.

No difference. After a longer pause followed by a resume, there's roughly 15 seconds of music left before it stops. Sometimes it continues on its own after a while, most of the time I have to manually interfere. I can reproduce the brief pause after buffered content (probably inside ffmpeg) is exhausted with 3.3 and 4.0. In an ideal world this shouldn’t happen. But pianobar always continues afterwards for me.

If I wait really long, Pandora even denies me access to the tracks in the current playlist (403). pianobar then cycles through the remaining playlist tracks, encounters 403 on all of them, then stops working altogether (instead of simply getting a new playlist) The 403 response is expected and there is nothing I can do about that.

@basicide You’re using ffmpeg. I can’t reproduce the issue on Linux with ffmpeg 4.0.2. This could be an issue exclusive to MacOS.

Can you (i.e. both of you) compile with debug symbols, attach a debugger and get a backtrace? I would like to know pianobar’s internal state when stuck.

basicide commented 5 years ago

I'm not exactly sure I did this right. I cloned the source, removed the -DNDEBUG flag from the Makefile, then built and ran. Looking at the logs it spit out in Console, this was the final one.

found no value for key 646F6E7A_00000000_00000001_6E7A6361_696D6963 in CFPrefsPlistSource<0x7fdacfd07180> (Domain: kCFPreferencesAnyApplication, User: kCFPreferencesCurrentUser, ByHost: No, Container: (null), Contents Need Refresh: No)

Not really a stack trace, but I wasn't sure of a better way to debug. If you have suggestions on how I should do this, I'm open to them.

haarp commented 5 years ago

Thanks for your response, PromyLOPh.

Prior to commit bbbdd99 there was no cache at all (and thus no switch to turn it on). Now a buffer for decoded audio exists, but its size is currently hard-coded: https://github.com/PromyLOPh/pianobar/blob/master/src/player.c#L437 You can try and play with it, but it won’t solve this problem.

It actually did! Setting the buffer to a very high number, like 15 minutes, avoids the problem entirely. Of course this isn't an universal solution.

I can reproduce the brief pause after buffered content (probably inside ffmpeg) is exhausted with 3.3 and 4.0. In an ideal world this shouldn’t happen. But pianobar always continues afterwards for me.

Yes, since testing the git sources it does continue on its own reliably, albeit only after a delay. Is this caused by a network timeout as I suspect? Maybe triggering a reconnect after a long pause would suffice to mitigate this.

The 403 response is expected and there is nothing I can do about that.

I understand that, but pianobar should continue afterwards, fetching a new playlist or re-login as necessary. In my experience it doesn't always do that. I'll check if the newest git sources offer better reliability.

PromyLOPh commented 5 years ago

@basicide: I usually refer to this guide, but I’m not sure i’ll work on MacOS: https://wiki.ubuntu.com/Backtrace#Generation

@haarp: I’ll expose this buffer size as a config file setting then. As for the pause: You can also try lowering the timeout setting. Currently it uses a very conservative 30 seconds. Cutting it down to something like 5 seconds while increasing the buffer size might help avoiding the pause completely. And yes, pianobar should continue in all cases. If it does not we’ll need to have a closer look at the state it is stuck in (i.e. a backtrace)'

basicide commented 5 years ago

@PromyLOPh well, in my testing and trying to get gdb to work, I noticed that the current development snapshot of pianobar started working properly for me and it also appears to have fixed the pausing issue.

haarp commented 5 years ago

After some testing with recent sources, I can say that pianobar resumes from 403s well. It just grabs a new playlist.

@haarp: I’ll expose this buffer size as a config file setting then.

Sweet! Thank you, that should solve this problem.

As for the pause: You can also try lowering the timeout setting. Currently it uses a very conservative 30 seconds. Cutting it down to something like 5 seconds.

This didn't yield good results. At 5 seconds, it occasionally times out while getting a playlist, and then stops.

basicide commented 5 years ago

I tried to see if I could remove my current homebrew version of pianobar and install it in place of and everything quit working. Now, with the -DNDEBUG flag removed, every time I try to run make clean && make, I get the following error:

src/libpiano/response.c:275:30: warning: result of comparison of constant 4 with expression of type 'PianoAudioQuality_t' is always true [-Wtautological-constant-out-of-range-compare] ...assert (reqData->quality < sizeof (qualityMap)/sizeof (*qualityMap));


/usr/include/assert.h:93:25: note: expanded from macro 'assert'
    (__builtin_expect(!(e), 0) ? __assert_rtn(__func__, __FILE__, __LINE__, #e) : (void)0)

Additionally, I'm back to the timer not working and the whole thing freezing after 5 seconds of playing and becoming unresponsive thereafter, even if I build using the -DNDEBUG flag.
haarp commented 5 years ago

Celebrated too early. Just had pianobar stop after encountering the remaining 403s in a playlist.

PromyLOPh commented 5 years ago

@basicide This is not an error, just a warning. Any idea what changed between your last two comments (working/not working)? @haarp Can you increase the setting max_retry? pianobar stops after three soft failures (includes 403’s) by default.

basicide commented 5 years ago

I actually do remember what I changed. I removed my homebrew installation of pianobar and ran “make install” on my dev snapshot. After that it wouldn’t work when running “pianobar” from my default directory or running “./pianobar” from the directory with the snapshot.

haarp commented 5 years ago

@haarp Can you increase the setting max_retry? pianobar stops after three soft failures (includes 403’s) by default.

Oh, it counts 403s as an error? I didn't know that! Yes, higher max_retry fixes this problem. Thanks!

I think it would be sensible to raise the default max_retry to 4, since a playlist contains 4 entries aswell.

PromyLOPh commented 5 years ago

Yeah. not ideal. I bumped it up to 5, because – again not ideal – the name is wrong. It’s not the number of retries, but number of failures tolerated. I also exposed the player’s buffer size via a config setting.

@basicide So that means 2018.06.22 worked a litte and -dev is just broken. Hm, I can’t debug this issue without access to Mac OS unfortunately, so I’ll have to figure out how to set up a VM – if that’s even possible.

basicide commented 5 years ago

I think you can set up a VM of Mac OS inside VirtualBox. Here's a guide for Windows 10, haven't found one for Linux yet. https://www.howtogeek.com/289594/how-to-install-macos-sierra-in-virtualbox-on-windows-10/

basicide commented 5 years ago

I tried to get a backtrace on the dev build of Pianobar using Xcode. This is what it generated.

* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00007fff60bfde82 libsystem_kernel.dylib`__select + 10
    frame #1: 0x00000001059faae5 pianobar`BarReadline + 197
    frame #2: 0x00000001059f3d22 pianobar`main + 2178
    frame #3: 0x00007fff60abe08d libdyld.dylib`start + 1
    frame #4: 0x00007fff60abe08d libdyld.dylib`start + 1

Hopefully that is more helpful than my previous log.

PromyLOPh commented 5 years ago

Yes, this is what I expect to see for thread #1. Do you have any information on the other threads?

basicide commented 5 years ago

Just figured out how to do a full backtrace. Results below.

* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00007fff60bfde82 libsystem_kernel.dylib`__select + 10
    frame #1: 0x0000000105945ae5 pianobar`BarReadline + 197
    frame #2: 0x000000010593ed22 pianobar`main + 2178
    frame #3: 0x00007fff60abe08d libdyld.dylib`start + 1
    frame #4: 0x00007fff60abe08d libdyld.dylib`start + 1
  thread #2
    frame #0: 0x00007fff60bfa1b2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff60cb35cb libsystem_pthread.dylib`_pthread_cond_wait + 724
    frame #2: 0x000000010593f8ea pianobar`BarPlayerThread + 1162
    frame #3: 0x00007fff60cb0339 libsystem_pthread.dylib`_pthread_body + 126
    frame #4: 0x00007fff60cb32a7 libsystem_pthread.dylib`_pthread_start + 70
    frame #5: 0x00007fff60caf445 libsystem_pthread.dylib`thread_start + 13
  thread #3
    frame #0: 0x00007fff60bfa1b2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff60cb35cb libsystem_pthread.dylib`_pthread_cond_wait + 724
    frame #2: 0x0000000106f3165b libavutil.56.dylib`___lldb_unnamed_symbol146$$libavutil.56.dylib + 124
    frame #3: 0x00007fff60cb0339 libsystem_pthread.dylib`_pthread_body + 126
    frame #4: 0x00007fff60cb32a7 libsystem_pthread.dylib`_pthread_start + 70
    frame #5: 0x00007fff60caf445 libsystem_pthread.dylib`thread_start + 13
  thread #4
    frame #0: 0x00007fff60bfa1b2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff60cb35cb libsystem_pthread.dylib`_pthread_cond_wait + 724
    frame #2: 0x0000000106f3165b libavutil.56.dylib`___lldb_unnamed_symbol146$$libavutil.56.dylib + 124
    frame #3: 0x00007fff60cb0339 libsystem_pthread.dylib`_pthread_body + 126
    frame #4: 0x00007fff60cb32a7 libsystem_pthread.dylib`_pthread_start + 70
    frame #5: 0x00007fff60caf445 libsystem_pthread.dylib`thread_start + 13
  thread #5
    frame #0: 0x00007fff60bfa1b2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff60cb35cb libsystem_pthread.dylib`_pthread_cond_wait + 724
    frame #2: 0x0000000106f3165b libavutil.56.dylib`___lldb_unnamed_symbol146$$libavutil.56.dylib + 124
    frame #3: 0x00007fff60cb0339 libsystem_pthread.dylib`_pthread_body + 126
    frame #4: 0x00007fff60cb32a7 libsystem_pthread.dylib`_pthread_start + 70
    frame #5: 0x00007fff60caf445 libsystem_pthread.dylib`thread_start + 13
  thread #6
    frame #0: 0x00007fff60bfa1b2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff60cb35cb libsystem_pthread.dylib`_pthread_cond_wait + 724
    frame #2: 0x0000000106f3165b libavutil.56.dylib`___lldb_unnamed_symbol146$$libavutil.56.dylib + 124
    frame #3: 0x00007fff60cb0339 libsystem_pthread.dylib`_pthread_body + 126
    frame #4: 0x00007fff60cb32a7 libsystem_pthread.dylib`_pthread_start + 70
    frame #5: 0x00007fff60caf445 libsystem_pthread.dylib`thread_start + 13
  thread #7
    frame #0: 0x00007fff60bfa1b2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff60cb35cb libsystem_pthread.dylib`_pthread_cond_wait + 724
    frame #2: 0x0000000106f3165b libavutil.56.dylib`___lldb_unnamed_symbol146$$libavutil.56.dylib + 124
    frame #3: 0x00007fff60cb0339 libsystem_pthread.dylib`_pthread_body + 126
    frame #4: 0x00007fff60cb32a7 libsystem_pthread.dylib`_pthread_start + 70
    frame #5: 0x00007fff60caf445 libsystem_pthread.dylib`thread_start + 13
  thread #8
    frame #0: 0x00007fff60bfa1b2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff60cb35cb libsystem_pthread.dylib`_pthread_cond_wait + 724
    frame #2: 0x0000000106f3165b libavutil.56.dylib`___lldb_unnamed_symbol146$$libavutil.56.dylib + 124
    frame #3: 0x00007fff60cb0339 libsystem_pthread.dylib`_pthread_body + 126
    frame #4: 0x00007fff60cb32a7 libsystem_pthread.dylib`_pthread_start + 70
    frame #5: 0x00007fff60caf445 libsystem_pthread.dylib`thread_start + 13
  thread #9
    frame #0: 0x00007fff60bfa1b2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff60cb35cb libsystem_pthread.dylib`_pthread_cond_wait + 724
    frame #2: 0x0000000106f3165b libavutil.56.dylib`___lldb_unnamed_symbol146$$libavutil.56.dylib + 124
    frame #3: 0x00007fff60cb0339 libsystem_pthread.dylib`_pthread_body + 126
    frame #4: 0x00007fff60cb32a7 libsystem_pthread.dylib`_pthread_start + 70
    frame #5: 0x00007fff60caf445 libsystem_pthread.dylib`thread_start + 13
  thread #10
    frame #0: 0x00007fff60bfa1b2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff60cb35cb libsystem_pthread.dylib`_pthread_cond_wait + 724
    frame #2: 0x0000000106f3165b libavutil.56.dylib`___lldb_unnamed_symbol146$$libavutil.56.dylib + 124
    frame #3: 0x00007fff60cb0339 libsystem_pthread.dylib`_pthread_body + 126
    frame #4: 0x00007fff60cb32a7 libsystem_pthread.dylib`_pthread_start + 70
    frame #5: 0x00007fff60caf445 libsystem_pthread.dylib`thread_start + 13
  thread #11
    frame #0: 0x00007fff60caf428 libsystem_pthread.dylib`start_wqthread
  thread #14
    frame #0: 0x00007fff60bfa1b2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fff60cb35cb libsystem_pthread.dylib`_pthread_cond_wait + 724
    frame #2: 0x0000000105940330 pianobar`BarAoPlayThread + 432
    frame #3: 0x00007fff60cb0339 libsystem_pthread.dylib`_pthread_body + 126
    frame #4: 0x00007fff60cb32a7 libsystem_pthread.dylib`_pthread_start + 70
    frame #5: 0x00007fff60caf445 libsystem_pthread.dylib`thread_start + 13
  thread #15, name = 'com.apple.audio.IOThread.client'
    frame #0: 0x00007fff60bf6c2a libsystem_kernel.dylib`mach_msg_trap + 10
    frame #1: 0x00007fff60bf7174 libsystem_kernel.dylib`mach_msg + 60
    frame #2: 0x00007fff3332c89a CoreAudio`HALB_MachPort::SendMessageWithReply(unsigned int, unsigned int, unsigned int, unsigned int, mach_msg_header_t*, bool, unsigned int) + 124
    frame #3: 0x00007fff3332c80d CoreAudio`HALB_MachPort::SendSimpleMessageWithSimpleReply(unsigned int, unsigned int, int, int&, bool, unsigned int) + 45
    frame #4: 0x00007fff33328b84 CoreAudio`HALC_ProxyIOContext::IOWorkLoop() + 988
    frame #5: 0x00007fff333285ee CoreAudio`HALC_ProxyIOContext::IOThreadEntry(void*) + 128
    frame #6: 0x00007fff333280d6 CoreAudio`HALB_IOThread::Entry(void*) + 72
    frame #7: 0x00007fff60cb0339 libsystem_pthread.dylib`_pthread_body + 126
    frame #8: 0x00007fff60cb32a7 libsystem_pthread.dylib`_pthread_start + 70
    frame #9: 0x00007fff60caf445 libsystem_pthread.dylib`thread_start + 13
  thread #16
    frame #0: 0x00007fff60caf428 libsystem_pthread.dylib`start_wqthread
  thread #17
    frame #0: 0x00007fff60bf6c7e libsystem_kernel.dylib`semaphore_timedwait_trap + 10
    frame #1: 0x00007fff60a7042c libdispatch.dylib`_dispatch_sema4_timedwait + 76
    frame #2: 0x00007fff60a70b1d libdispatch.dylib`_dispatch_semaphore_wait_slow + 58
    frame #3: 0x00007fff60a7db66 libdispatch.dylib`_dispatch_worker_thread + 328
    frame #4: 0x00007fff60cb0339 libsystem_pthread.dylib`_pthread_body + 126
    frame #5: 0x00007fff60cb32a7 libsystem_pthread.dylib`_pthread_start + 70
    frame #6: 0x00007fff60caf445 libsystem_pthread.dylib`thread_start + 13
  thread #18
    frame #0: 0x00007fff60bf85be libsystem_kernel.dylib`__workq_kernreturn + 10
    frame #1: 0x00007fff60caf661 libsystem_pthread.dylib`_pthread_wqthread + 446
    frame #2: 0x00007fff60caf435 libsystem_pthread.dylib`start_wqthread + 13
  thread #19
    frame #0: 0x00007fff60bf85be libsystem_kernel.dylib`__workq_kernreturn + 10
    frame #1: 0x00007fff60caf661 libsystem_pthread.dylib`_pthread_wqthread + 446
    frame #2: 0x00007fff60caf435 libsystem_pthread.dylib`start_wqthread + 13
liuche commented 5 years ago

I get pianobar from homebrew - running brew info pianobar said it wasn't linked to ffmpeg. After installing ffmpeg all these dropped streams, delayed start, all fixed! 🙌

@basicide you mentioned you use homebrew on a mac, but couldn't figure out whether pianobar was linked against ffmpeg - is this helpful? ^

PromyLOPh commented 5 years ago

@basicide Unfortunately there are no line numbers in your backtrace, but thread 2 and 14 seems to be stuck. From your description of the problem (pianobar is stuck after 5 seconds) there are two scenarios that would make sense: a) The playback is – somehow – interrupted, pianobar’s buffer runs full and it gets stuck after that. And b) both threads are waiting for data, which is not arriving (i.e. network connection dropped). Does pianobar respond to Ctrl-C (^C/SIGINT) when stuck?

basicide commented 5 years ago

It doesn’t respond to Ctrl-C or any other input. I have to kill my Terminal session.

PromyLOPh commented 5 years ago

Sorry for the delay. I added some debug code in the branch “debug”. Can you recompile without -DNDEBUG and run PIANOBAR_DEBUG=1 ./pianobar? Hopefully this gets us closer to solving this issue.

basicide commented 5 years ago

Here's what happened when I tried to make clean && make.

CLEAN
    CC  src/main.c
src/main.c:405:3: warning: implicit declaration of function 'debugPrint' is invalid in C99
      [-Wimplicit-function-declaration]
                debugPrint("Received ^C\n");
                ^
src/main.c:422:2: warning: implicit declaration of function 'debugEnable' is invalid in C99
      [-Wimplicit-function-declaration]
        debugEnable();
        ^
2 warnings generated.
make: *** No rule to make target `src/debug.o', needed by `pianobar'.  Stop.
PromyLOPh commented 5 years ago

Oops, I forgot to add src/debug.[ch]. My bad. Pull and try again.

basicide commented 5 years ago

Okay, so it's working currently. Songs are playing longer than 5 seconds and the timer is running. I can pause and resume without it skipping tracks. Some interesting things I noticed from the output that may or may not be informative.

I get other errors when I make.

 CLEAN
    CC  src/main.c
    CC  src/debug.c
    CC  src/player.c
src/player.c:449:8: warning: format specifies type 'long' but the argument has type 'int64_t'
      (aka 'long long') [-Wformat]
                                                        bufferHealth, minBufferHealth);
                                                        ^~~~~~~~~~~~
src/player.c:449:22: warning: format specifies type 'long' but the argument has type 'int64_t'
      (aka 'long long') [-Wformat]
                                                        bufferHealth, minBufferHealth);
                                                                      ^~~~~~~~~~~~~~~
src/player.c:455:8: warning: format specifies type 'long' but the argument has type 'int64_t'
      (aka 'long long') [-Wformat]
                                                        bufferHealth, minBufferHealth);
                                                        ^~~~~~~~~~~~
src/player.c:455:22: warning: format specifies type 'long' but the argument has type 'int64_t'
      (aka 'long long') [-Wformat]
                                                        bufferHealth, minBufferHealth);
                                                                      ^~~~~~~~~~~~~~~
4 warnings generated.
    CC  src/settings.c
    CC  src/terminal.c
    CC  src/ui_act.c
    CC  src/ui.c
    CC  src/ui_readline.c
    CC  src/ui_dispatch.c
    CC  src/libpiano/crypt.c
    CC  src/libpiano/piano.c
    CC  src/libpiano/request.c
    CC  src/libpiano/response.c
src/libpiano/response.c:275:30: warning: result of comparison of constant 4 with expression of type
      'PianoAudioQuality_t' is always true [-Wtautological-constant-out-of-range-compare]
  ...assert (reqData->quality < sizeof (qualityMap)/sizeof (*qualityMap));
             ~~~~~~~~~~~~~~~~ ^ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
/usr/include/assert.h:93:25: note: expanded from macro 'assert'
    (__builtin_expect(!(e), 0) ? __assert_rtn(__func__, __FILE__, __LINE__, #e) : (void)0)
                        ^
1 warning generated.
    CC  src/libpiano/list.c
  LINK  pianobar

When I'm running pianobar, I see these two lines repeating while music is playing.

ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5

There's also some incredibly long json strings that happen right after I run PIANOBAR_DEBUG=1 ./pianobar that I didn't include since I wasn't sure if there was any secure info in there.

PromyLOPh commented 5 years ago

That’s interesting. I was not expecting a few printf’s would fix the problem. Does the issue reappear without PIANOBAR_DEBUG=1?

The compiler warnings seem non-fatal, the lines regarding “needs more data” and “buffer filled” are expected in this debug mode and look fine and finally these JSON strings may contains sensitive information, but they’re not important in this case anyway.

basicide commented 5 years ago

Surprisingly, the issue does not reappear. I tried to see if the issue would happen again if I completely deleted the repo and did a fresh pull from debug. After a make clean && make, ./pianobar runs normally. I even ran make install and called pianobar from ~/ and it ran normally as well. I wonder if something upstream has been causing this the whole time?

basicide commented 5 years ago

For reference, the master branch is working for me now too.

PromyLOPh commented 5 years ago

Did you switch to a new compiler version perhaps?

basicide commented 5 years ago

I'm not sure. My make is located at /usr/bin/make which I think is part of macOS. I did update to 10.14.2 on Dec 5, so that could be it.

basicide commented 5 years ago

Believe it or not, it has stopped working again. No updates to my compiler this time as far as I'm aware. I repeated the steps from before and it did the thing where it would play for 5 seconds and stop without the timer moving forward at all. This was the last line it printed out before it became unresponsive.

ao player is waiting for more frames after code -35

PromyLOPh commented 5 years ago

Interesting. Can you post the last 10 to 20 lines, so I can figure out what the buffer thread is doing?

basicide commented 5 years ago

After it starts, I get a lot of these lines until the end. 

ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao player is waiting for more frames after code -35
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao player is waiting for more frames after code -35
PromyLOPh commented 5 years ago

Looks like I can inject this error with the same results you get (unresponsive client). Apparently the player waits for the condition to be broadcast, but the buffer is full so the buffer thread never does that → deadlock. Applying the following patch on top of the debug branch fixes the issue for me: https://gist.github.com/PromyLOPh/325e301703f2ac349d3a960982b30de6

Can you confirm this?

basicide commented 5 years ago

When I run git apply /PATH/TO/deadlock.patch I get back error: corrupt patch at line 12. All I see on line 12 is continue; so I'm not sure why it's failing to apply.

PromyLOPh commented 5 years ago

Not sure either. Just add the following line to src/player.c after line 543 (debugPrint):

pthread_cond_broadcast (&player->aoplayCond);

basicide commented 5 years ago

After doing that, the issue still occurs, but this is what the output looks like right before and right after it freezes.

decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao player is waiting for more frames after code -35
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao player is waiting for more frames after code -35
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao player is waiting for more frames after code -35
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao player is waiting for more frames after code -35
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao player is waiting for more frames after code -35
ao play signalled it needs more data health 6 minHealth 5
PromyLOPh commented 5 years ago

So the deadlock is just the result of that error, not its cause. Can you pull the debug branch and reapply the change above (pthread_cond_broadcast)? I think error -35 is EAGAIN on macOS 10.12[1], but I want to be sure.

[1] https://opensource.apple.com/source/xnu/xnu-3789.70.16/bsd/sys/errno.h.auto.html

basicide commented 5 years ago

Here's the output I'm getting now.

ao player is waiting for more frames after code -35 (Resource temporarily unavailable)
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5
ao player is waiting for more frames after code -35 (Resource temporarily unavailable)
ao play signalled it needs more data health 6 minHealth 5
decoding buffer filled health 6 minHealth 5

Something interesting I noticed though is that right as the station is starting I get one instance of that line with error code -35 before it starts flipping back and forth between the ao play and decoding buffer lines before dying and repeating all 3 again. So something may be happening right away and it just takes about 5 seconds for the very first buffer to run out. Not sure if that's helpful info or not.

PromyLOPh commented 5 years ago

Thanks, this confirms EAGAIN.

When starting the player thread the buffer is empty, so the first EAGAIN is expected. I’m just a little puzzled why it starts happening again. The buffer is definitely full (decoding buffer filled health 6 minHealth 5), unless that calculation is somehow wrong.

Can you increase the setting buffer_seconds to some absurdly high value like 100000? (minHealth in the debug output)

basicide commented 5 years ago

So I bumped it to 1,000,000 and it took about 5 minutes to start playing. The song did not stop playing after 5 seconds like before, but the timer wasn't ticking at the bottom either. This was the output. 

ao player is waiting for more frames after code -35 (Resource temporarily unavailable)
decoder entering drain mode after EOF
receive_frame got EOF, sending NULL frame
decoder is done, waiting for ao player
PromyLOPh commented 5 years ago

But pianobar was responsive (key press, next song, quit, …)?

Can you tell me the exact compiler version you’re using right now (gcc --version) and try compiling with a different compiler (clang, for example; make clean && make CC=clang V=1 CFLAGS="-O0 -g")? Please verify make’s output to ensure it actually uses a different compiler and the CFLAGS provided.

basicide commented 5 years ago

Lots of info incoming. Here's the output of gcc --version.

Configured with: --prefix=/Library/Developer/CommandLineTools/usr --with-gxx-include-dir=/usr/include/c++/4.2.1
Apple LLVM version 10.0.0 (clang-1000.10.44.4)
Target: x86_64-apple-darwin18.2.0
Thread model: posix
InstalledDir: /Library/Developer/CommandLineTools/usr/bin

I then ran make clean && make CC=clang V=1 CFLAGS="-O0 -g and got the following output.

CLEAN
clang -c -o src/main.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/main.d -MP src/main.c
clang -c -o src/debug.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/debug.d -MP src/debug.c
clang -c -o src/player.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/player.d -MP src/player.c
src/player.c:449:8: warning: format specifies type 'long' but the argument has type 'int64_t'
      (aka 'long long') [-Wformat]
                                                        bufferHealth, minBufferHealth);
                                                        ^~~~~~~~~~~~
src/player.c:449:22: warning: format specifies type 'long' but the argument has type 'int64_t'
      (aka 'long long') [-Wformat]
                                                        bufferHealth, minBufferHealth);
                                                                      ^~~~~~~~~~~~~~~
src/player.c:455:8: warning: format specifies type 'long' but the argument has type 'int64_t'
      (aka 'long long') [-Wformat]
                                                        bufferHealth, minBufferHealth);
                                                        ^~~~~~~~~~~~
src/player.c:455:22: warning: format specifies type 'long' but the argument has type 'int64_t'
      (aka 'long long') [-Wformat]
                                                        bufferHealth, minBufferHealth);
                                                                      ^~~~~~~~~~~~~~~
4 warnings generated.
clang -c -o src/settings.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/settings.d -MP src/settings.c
clang -c -o src/terminal.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/terminal.d -MP src/terminal.c
clang -c -o src/ui_act.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/ui_act.d -MP src/ui_act.c
clang -c -o src/ui.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/ui.d -MP src/ui.c
clang -c -o src/ui_readline.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/ui_readline.d -MP src/ui_readline.c
clang -c -o src/ui_dispatch.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/ui_dispatch.d -MP src/ui_dispatch.c
clang -c -o src/libpiano/crypt.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/libpiano/crypt.d -MP src/libpiano/crypt.c
clang -c -o src/libpiano/piano.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/libpiano/piano.d -MP src/libpiano/piano.c
clang -c -o src/libpiano/request.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/libpiano/request.d -MP src/libpiano/request.c
clang -c -o src/libpiano/response.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/libpiano/response.d -MP src/libpiano/response.c
src/libpiano/response.c:275:30: warning: result of comparison of constant 4 with expression of type
      'PianoAudioQuality_t' is always true [-Wtautological-constant-out-of-range-compare]
  ...assert (reqData->quality < sizeof (qualityMap)/sizeof (*qualityMap));
             ~~~~~~~~~~~~~~~~ ^ ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
/usr/include/assert.h:93:25: note: expanded from macro 'assert'
    (__builtin_expect(!(e), 0) ? __assert_rtn(__func__, __FILE__, __LINE__, #e) : (void)0)
                        ^
1 warning generated.
clang -c -o src/libpiano/list.o -O0 -g -I src/libpiano -I/usr/local/Cellar/ffmpeg/4.1_1/include   -I/usr/local/Cellar/json-c/0.13.1/include/json-c -I/usr/local/Cellar/libao/1.2.2/include -MMD -MF src/libpiano/list.d -MP src/libpiano/list.c
clang -o pianobar src/main.o src/debug.o src/player.o src/settings.o src/terminal.o src/ui_act.o src/ui.o src/ui_readline.o src/ui_dispatch.o src/libpiano/crypt.o src/libpiano/piano.o src/libpiano/request.o src/libpiano/response.o src/libpiano/list.o  -lpthread -lm -L/usr/local/Cellar/ffmpeg/4.1_1/lib -lavcodec -lavformat -lavutil -lavfilter -lcurl -lgcrypt -L/usr/local/Cellar/json-c/0.13.1/lib -ljson-c -L/usr/local/Cellar/libao/1.2.2/lib -lao

I ran PIANOBAR_DEBUG=1 ./pianobar next. As before, buffer_seconds was set to 1,000,000 but this time it played without a 5 minute load time. Both this time and last time I tested, it was responsive to me pausing, playing, skipping tracks, and quitting.

PromyLOPh commented 5 years ago

Ah, so gcc is actually clang on macOS. Since it seems to be working fine without any compiler optimizations (-O0) this hints at a compiler issue.

I pushed the deadlock fix, but apart from that I’d say the only workaround right now is compiling with -O0 -g. Is that alright for you?

basicide commented 5 years ago

That works for me. I pulled master down and compiled with those flags and it's running normally, responding to input, not timing out. The only thing not working at this point is the timer at the bottom. It shows the initial length of the song and never moves, i.e. 4:02/4:02, even as the song plays along and if I skip to another song the time will change to the new song's length, i.e. 3:46/3:46, but it still isn't ticking along. Is that a result of something we've done above?