Moc on Raspberry Pi 3 - Curios behavior on startup

Submitted by RasPi on Tue, 2016-11-29 10:16

Forums:

Hi everyone,

I'm running MOC on an Raspberry Pi 3 with the latest raspbian release from within a Python script.

Currently I'm building a very simple audio player working like this:
- scan album title from a qr code (this is a process within a while loop)
- if the qr code is read successfully, play a confirmation tone and start playing album from sc card
- otherwise play an error tone

This works quite well when the engine is running. But on startup I'm expierencing a very curios behavior:
- when I tell the Pi to scan a code,
- the code is scanned, the confirmation tone is played 3 to 5 times (this part is not within the loop)
- another tone that sounds like an explosion is played
- and finally the album is played

After 2 or 3 times with this behaviour it seems the Pi and Mocp is "ready" and everything works fine ...

The explosion sound is not set by me - is this a standard sound by moc?
Has anyone else already expierenced such a behaviour and knows how to fix that?

Any help is appreciated.

Thanks!

tomaszg

Tue, 2016-11-29 10:42

I didn't run MOC on RPi, but I run it on OpenWRT router and I didn't hear anything similar to what you describe. You might try to record debug log for MOC (mocp -D) and see what happens when the explosion sound is heard.

I must say I like your idea of controlling MOC via qrcodes. I'm still struggling with good ways to control my OpenWRT MOC (other than via ssh) and it looks interesting. Do you just use a webcam, or some dedicated code reader?

RasPi

Tue, 2016-11-29 12:04

Hi,

it's just a simple USB webcam I bought on Ebay for 5 Euro - it was the cheapest device I found and works via plug and play. I also found other projects using RFID, so maybe that might be another handy way for you.

Currently I run moc via pyhton script and therefore don't use a frontend. How can I view the debug log when I run moc via mocp -D?

tomaszg

Tue, 2016-11-29 12:08

The log is just recorded to the file mocp_server_log in the working directory. It can be quite lengthy but some hints might be hidden there.

RFID tags are also a good idea - but in both cases there is a problem with a "library" of tags to be scanned. I'll keep thinking ;)

RasPi

Thu, 2016-12-01 09:05

I tried to launch the debug mode via mocp -D but there is only the file mocp_client_log generated. In this log I can only find, that the confirmation sound is played multiple times.

What did I do wrong that the server_log is not generated?

tomaszg

Thu, 2016-12-01 09:08

Probably the server was already running without -D, so only client saw the new option.

RasPi

Fri, 2016-12-02 08:05

You're right - I found the code where the server was already run without debug mode. So you really helped me, the explosion sound was somewhere in the raspbain system provided by a preinstalled game :-)

But now I'm struggling with my Python code, something isn't working as expected...

Have you already seen that:
http://www.forum-raspberrypi.de/Thread-projekt-jukebox4kids-jukebox-fuer-kinder

Maybe watching that you're not "afraid" of the library-problem any more :-)

tomaszg

Fri, 2016-12-02 11:37

Nice realisation - I might try to do something like that for my kid. However I need also something for adults. When you have for example 500+ albums keeping RFID tags for them around is not the easiest solution. Maybe it would just be possible to run MOC on such LCD screen ;)

RasPi

Fri, 2016-12-02 19:43

I'm also doing that for my kid - it's her Christmas present i'm just working on.

I made some updates to my python script ... but running in the next problem. I'm a little stressed because of the time going by ...

Had you ever such problem: calling mocp --next or --previous stops playback and does not navigate through the playlist. I also can't find a hind in the logs.
This used to work, but I manipualetd my script on a different place that might not affect this.

tomaszg

Fri, 2016-12-02 20:06

I didn't notice such behaviour but I rarely use command line options. Maybe for some reason some files cause mocp server to hang? Only serious issue I had on OpenWRT was related to non-ascii characters - they are sometimes garbled or even cause MOC to crash. However I think it is caused by slimmed down version of libiconv shipped with openwrt.

RasPi

Tue, 2016-12-06 20:06

Well, I experimented a lot but I have no clue why it's not working. Sometimes the "next" statement works fine, sometimes it causes Moc to stop. Previous isn't working at all.
Pressing "Pause" only works fine if Moc Client is not opened in the console.. I think I'll check if another player works more reliable to me :(

tomaszg

Tue, 2016-12-06 20:22

But do you see anything suspicious in the log after issuing these commands? Does it work when you try it manually (outside of the script)?

RasPi

Wed, 2016-12-07 18:47

Typing the commands in Command line everything works fine...but not inside the script. Today I really found the first time a crude statement in the server log:

Dec 7 19:39:58.082876: audio.c:377 go_to_another_file(): Playing next...
Dec 7 19:39:58.082896: audio.c:398 go_to_another_file(): End of the list
...
Dec 7 19:39:58.083521: alsa.c:580 alsa_close(): ALSA device closed
Dec 7 19:39:58.083545: audio.c:490 play_thread(): Exiting

Starting playback again works fine, so the player is still running.

Any idea?

RasPi

Wed, 2016-12-07 19:16

That's the full log beginning from the "next" statement:

Dec 7 19:39:57.857975: audio.c:377 go_to_another_file(): Playing next... Dec 7 19:39:57.858022: audio.c:400 go_to_another_file(): Next item Dec 7 19:39:57.858071: audio.c:438 play_thread(): Playing item 1: /home/pi/Musik/Conni/test.mp3 Dec 7 19:39:57.858122: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.858198: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.858246: out_buf.c:339 out_buf_reset(): resetting the buffer Dec 7 19:39:57.858289: player.c:354 precache_wait(): Precache thread is not running Dec 7 19:39:57.858330: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.858380: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.858421: io.c:471 io_open_file(): Not using mmap() Dec 7 19:39:57.858481: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.858580: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.858653: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.858717: io.c:351 io_read_thread(): IO read thread created Dec 7 19:39:57.859379: mp3.c:257 count_time_internal(): Detected VBR after 2 frames Dec 7 19:39:57.925958: mp3.c:309 count_time_internal(): Counted duration by counting frames durations in VBR file. Dec 7 19:39:57.926059: mp3.c:320 count_time_internal(): MP3 time: 299 Dec 7 19:39:57.926084: io.c:170 io_seek_buffered(): Seeking... Dec 7 19:39:57.926114: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.926203: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.926314: audio.c:1168 audio_plist_set_time(): Setting time for /home/pi/Musik/Conni/test.mp3 Dec 7 19:39:57.926382: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.926416: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.926448: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.926472: player.c:470 decode_loop(): loop... Dec 7 19:39:57.926495: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.926527: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.926548: io.c:591 io_prebuffer(): done Dec 7 19:39:57.926569: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.926594: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.926626: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.926649: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.927087: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.927115: player.c:172 bitrate_list_add(): Adding bitrate 320 at time 0 Dec 7 19:39:57.927138: player.c:591 decode_loop(): Sound parameters have changed. Dec 7 19:39:57.927156: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.927179: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.927206: out_buf.c:417 out_buf_wait(): Waiting for read thread to suspend... Dec 7 19:39:57.927226: out_buf.c:426 out_buf_wait(): done Dec 7 19:39:57.927251: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.927288: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.927310: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.927755: alsa.c:580 alsa_close(): ALSA device closed Dec 7 19:39:57.927794: audio.c:259 sfmt_best_matching(): Chose 16-bit signed little-endian (native) as the best matching 24-bit signed (as 32-bit samples) little-endian (native) Dec 7 19:39:57.928108: alsa.c:419 alsa_open(): Set rate to 48000 Dec 7 19:39:57.928494: tags_cache.c:814 tags_cache_add_request(): Request for tags for '/home/pi/Musik/Conni/test.mp3' from client 0 Dec 7 19:39:57.928644: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.928674: tags_cache.c:793 locked_add_request(): Tags are present in the cache Dec 7 19:39:57.928703: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.928729: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.929349: alsa.c:466 alsa_open(): Buffer time: 300000us Dec 7 19:39:57.929376: alsa.c:477 alsa_open(): Chunk size: 14400 Dec 7 19:39:57.930172: alsa.c:487 alsa_open(): ALSA device opened Dec 7 19:39:57.930209: audio.c:738 audio_open(): Conversion of the sound is needed. Dec 7 19:39:57.930235: audio.c:752 audio_open(): Requested sound parameters: 24-bit signed (as 32-bit samples) little-endian (native), 2 channels, 48000Hz Dec 7 19:39:57.930258: audio.c:756 audio_open(): Driver sound parameters: 16-bit signed little-endian (native), 2 channels, 48000Hz Dec 7 19:39:57.930276: player.c:470 decode_loop(): loop... Dec 7 19:39:57.930297: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.930375: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.930410: player.c:470 decode_loop(): loop... Dec 7 19:39:57.930433: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.930454: io.c:591 io_prebuffer(): done Dec 7 19:39:57.930477: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.930506: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.930542: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 4608 bytes) Dec 7 19:39:57.930565: alsa.c:548 play_buf_chunks(): 4608 bytes remain in alsa_buf Dec 7 19:39:57.930587: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.930613: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.930644: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.930671: player.c:212 bitrate_list_get(): Getting bitrate for time 0 (320) Dec 7 19:39:57.930740: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.930767: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.930820: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.930845: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.930972: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.931003: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.931033: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.931111: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.931140: player.c:470 decode_loop(): loop... Dec 7 19:39:57.931178: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.931206: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 9216 bytes) Dec 7 19:39:57.931227: alsa.c:548 play_buf_chunks(): 9216 bytes remain in alsa_buf Dec 7 19:39:57.931250: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.931275: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.931295: io.c:591 io_prebuffer(): done Dec 7 19:39:57.931314: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.931342: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.931371: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.931792: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.931814: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.931835: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.931908: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.931933: player.c:470 decode_loop(): loop... Dec 7 19:39:57.931954: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.931982: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 13824 bytes) Dec 7 19:39:57.932004: alsa.c:548 play_buf_chunks(): 13824 bytes remain in alsa_buf Dec 7 19:39:57.932036: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.932057: io.c:591 io_prebuffer(): done Dec 7 19:39:57.932079: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.932100: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.932128: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.932160: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.932559: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.932598: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.932621: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.932867: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.932908: player.c:470 decode_loop(): loop... Dec 7 19:39:57.932932: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.932981: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.933065: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 18432 bytes) Dec 7 19:39:57.933091: io.c:591 io_prebuffer(): done Dec 7 19:39:57.933117: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.933160: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.933201: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.933460: alsa.c:544 play_buf_chunks(): Played 14400 bytes Dec 7 19:39:57.933512: alsa.c:548 play_buf_chunks(): 4032 bytes remain in alsa_buf Dec 7 19:39:57.933539: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.933642: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.933672: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.933697: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.933781: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.933814: player.c:470 decode_loop(): loop... Dec 7 19:39:57.933888: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.933910: io.c:591 io_prebuffer(): done Dec 7 19:39:57.933932: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.933960: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.933992: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 8640 bytes) Dec 7 19:39:57.934015: alsa.c:548 play_buf_chunks(): 8640 bytes remain in alsa_buf Dec 7 19:39:57.934042: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.934068: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.934115: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.934429: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.934453: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.934473: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.934548: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.934574: player.c:470 decode_loop(): loop... Dec 7 19:39:57.934595: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.934614: io.c:591 io_prebuffer(): done Dec 7 19:39:57.934634: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.934662: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.934689: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 13248 bytes) Dec 7 19:39:57.934711: alsa.c:548 play_buf_chunks(): 13248 bytes remain in alsa_buf Dec 7 19:39:57.934735: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.934763: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.934793: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.935104: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.935126: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.935148: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.935220: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.935245: player.c:470 decode_loop(): loop... Dec 7 19:39:57.935270: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.935289: io.c:591 io_prebuffer(): done Dec 7 19:39:57.935310: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.935336: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.935364: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 17856 bytes) Dec 7 19:39:57.935388: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.935412: alsa.c:544 play_buf_chunks(): Played 14400 bytes Dec 7 19:39:57.935433: alsa.c:548 play_buf_chunks(): 3456 bytes remain in alsa_buf Dec 7 19:39:57.935453: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.935479: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.935781: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.935810: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.935833: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.935910: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.935938: player.c:470 decode_loop(): loop... Dec 7 19:39:57.935960: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.935979: io.c:591 io_prebuffer(): done Dec 7 19:39:57.936001: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.936033: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.936067: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.936111: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.936199: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 8064 bytes) Dec 7 19:39:57.936223: alsa.c:548 play_buf_chunks(): 8064 bytes remain in alsa_buf Dec 7 19:39:57.936244: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.936478: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.936503: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.936524: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.936597: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.936623: player.c:470 decode_loop(): loop... Dec 7 19:39:57.936645: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.936673: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 12672 bytes) Dec 7 19:39:57.936695: alsa.c:548 play_buf_chunks(): 12672 bytes remain in alsa_buf Dec 7 19:39:57.936720: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.936742: io.c:591 io_prebuffer(): done Dec 7 19:39:57.936762: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.936787: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.936820: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.936852: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.937239: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.937261: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.937281: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.937353: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.937378: player.c:470 decode_loop(): loop... Dec 7 19:39:57.937404: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.937423: io.c:591 io_prebuffer(): done Dec 7 19:39:57.937441: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.937472: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.937505: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.937570: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.937600: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 17280 bytes) Dec 7 19:39:57.937647: alsa.c:544 play_buf_chunks(): Played 14400 bytes Dec 7 19:39:57.937666: alsa.c:548 play_buf_chunks(): 2880 bytes remain in alsa_buf Dec 7 19:39:57.937684: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.937907: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.937933: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.937953: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.938025: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.938050: player.c:470 decode_loop(): loop... Dec 7 19:39:57.938129: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.938162: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 7488 bytes) Dec 7 19:39:57.938183: alsa.c:548 play_buf_chunks(): 7488 bytes remain in alsa_buf Dec 7 19:39:57.938206: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.938232: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.938251: io.c:591 io_prebuffer(): done Dec 7 19:39:57.938270: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.938302: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.938338: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.938751: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.938778: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.938799: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.938874: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.938906: player.c:470 decode_loop(): loop... Dec 7 19:39:57.938933: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.938952: io.c:591 io_prebuffer(): done Dec 7 19:39:57.938973: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.939000: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.939066: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 12096 bytes) Dec 7 19:39:57.939089: alsa.c:548 play_buf_chunks(): 12096 bytes remain in alsa_buf Dec 7 19:39:57.939113: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.939142: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.939173: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.939440: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.939463: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.939483: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.939555: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.939580: player.c:470 decode_loop(): loop... Dec 7 19:39:57.939606: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.939625: io.c:591 io_prebuffer(): done Dec 7 19:39:57.939646: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.939673: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.939701: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 16704 bytes) Dec 7 19:39:57.939726: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.939748: alsa.c:544 play_buf_chunks(): Played 14400 bytes Dec 7 19:39:57.939770: alsa.c:548 play_buf_chunks(): 2304 bytes remain in alsa_buf Dec 7 19:39:57.939791: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.939815: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.940114: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.940138: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.940159: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.940232: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.940259: player.c:470 decode_loop(): loop... Dec 7 19:39:57.940282: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.940301: io.c:591 io_prebuffer(): done Dec 7 19:39:57.940319: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.940351: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.940387: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.940416: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 6912 bytes) Dec 7 19:39:57.940438: alsa.c:548 play_buf_chunks(): 6912 bytes remain in alsa_buf Dec 7 19:39:57.940461: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.940486: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.940788: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.940810: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.940830: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.940902: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.940926: player.c:470 decode_loop(): loop... Dec 7 19:39:57.940946: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.940972: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 11520 bytes) Dec 7 19:39:57.940994: alsa.c:548 play_buf_chunks(): 11520 bytes remain in alsa_buf Dec 7 19:39:57.941020: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.941041: io.c:591 io_prebuffer(): done Dec 7 19:39:57.941061: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.941085: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:57.941112: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.941142: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.941525: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.941548: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.941568: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.941672: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.941701: player.c:470 decode_loop(): loop... Dec 7 19:39:57.941721: alsa.c:595 alsa_play(): Got 4608 bytes to play Dec 7 19:39:57.941748: alsa.c:607 alsa_play(): Copied 4608 bytes to alsa_buf (now filled with 16128 bytes) Dec 7 19:39:57.941775: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.941796: io.c:591 io_prebuffer(): done Dec 7 19:39:57.941817: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.941843: alsa.c:544 play_buf_chunks(): Played 1152 bytes Dec 7 19:39:57.941870: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.941900: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.942285: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.942308: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.942329: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.942401: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.942423: player.c:470 decode_loop(): loop... Dec 7 19:39:57.942444: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.942460: io.c:591 io_prebuffer(): done Dec 7 19:39:57.942478: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.942509: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.942537: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.942995: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.943023: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.943044: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.943117: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.943138: player.c:470 decode_loop(): loop... Dec 7 19:39:57.943160: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.943176: io.c:591 io_prebuffer(): done Dec 7 19:39:57.943194: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.943226: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.943256: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.943659: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.943682: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.943702: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.943775: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.943796: player.c:470 decode_loop(): loop... Dec 7 19:39:57.943816: io.c:581 io_prebuffer(): prebuffering to 65536 bytes... Dec 7 19:39:57.943832: io.c:591 io_prebuffer(): done Dec 7 19:39:57.943850: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:57.943879: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:57.943907: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:57.944316: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.944342: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.944365: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.944473: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.944507: player.c:470 decode_loop(): loop... Dec 7 19:39:57.945074: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.945126: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.945148: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.945242: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.945271: player.c:470 decode_loop(): loop... Dec 7 19:39:57.945735: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.945758: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.945809: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.945881: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.945901: player.c:470 decode_loop(): loop... Dec 7 19:39:57.946356: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.946378: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.946406: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.946497: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.946519: player.c:470 decode_loop(): loop... Dec 7 19:39:57.946967: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.946989: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.947008: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.947079: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.947099: player.c:470 decode_loop(): loop... Dec 7 19:39:57.947547: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.947567: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.947587: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.947657: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.947677: player.c:470 decode_loop(): loop... Dec 7 19:39:57.948124: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.948145: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.948164: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.948234: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.948254: player.c:470 decode_loop(): loop... Dec 7 19:39:57.948701: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.948722: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.948741: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.948812: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.948831: player.c:470 decode_loop(): loop... Dec 7 19:39:57.949280: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.949300: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.949320: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.949390: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.949410: player.c:470 decode_loop(): loop... Dec 7 19:39:57.949857: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.949878: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.949897: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.949968: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.949987: player.c:470 decode_loop(): loop... Dec 7 19:39:57.950434: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.950455: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.950474: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.950545: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.950564: player.c:470 decode_loop(): loop... Dec 7 19:39:57.951012: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.951032: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.951051: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.951122: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.951142: player.c:470 decode_loop(): loop... Dec 7 19:39:57.951634: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.951697: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.951719: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.951790: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.951810: player.c:470 decode_loop(): loop... Dec 7 19:39:57.952301: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.952328: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.952347: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.952427: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.952449: player.c:470 decode_loop(): loop... Dec 7 19:39:57.953004: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.953046: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.953067: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.953142: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.953163: player.c:470 decode_loop(): loop... Dec 7 19:39:57.953628: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.953653: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.953673: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.953763: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.953786: player.c:470 decode_loop(): loop... Dec 7 19:39:57.954300: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.954326: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.954347: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.954422: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.954445: player.c:470 decode_loop(): loop... Dec 7 19:39:57.954909: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.954934: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.954954: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.955026: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.955047: player.c:470 decode_loop(): loop... Dec 7 19:39:57.955508: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.955531: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.955551: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.955622: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.955645: player.c:470 decode_loop(): loop... Dec 7 19:39:57.956112: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.956141: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.956161: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.956235: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.956255: player.c:470 decode_loop(): loop... Dec 7 19:39:57.956710: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.956739: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.956758: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.956831: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.956859: player.c:470 decode_loop(): loop... Dec 7 19:39:57.957318: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.957340: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 0 because the bitrate hasn't changed Dec 7 19:39:57.957360: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.957431: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.957481: player.c:470 decode_loop(): loop... Dec 7 19:39:57.957943: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.957972: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.957992: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.958064: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.958085: player.c:470 decode_loop(): loop... Dec 7 19:39:57.958537: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.958558: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.958578: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.958649: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.958669: player.c:470 decode_loop(): loop... Dec 7 19:39:57.959129: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.959156: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.959177: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.959247: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.959267: player.c:470 decode_loop(): loop... Dec 7 19:39:57.959732: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.959753: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.959773: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.959843: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.959863: player.c:470 decode_loop(): loop... Dec 7 19:39:57.960311: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.960331: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.960351: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.960421: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.960441: player.c:470 decode_loop(): loop... Dec 7 19:39:57.960889: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.960910: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.960929: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.961000: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.961020: player.c:470 decode_loop(): loop... Dec 7 19:39:57.961467: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.961488: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.961508: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.961578: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.961598: player.c:470 decode_loop(): loop... Dec 7 19:39:57.962046: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.962067: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.962086: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.962157: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.962177: player.c:470 decode_loop(): loop... Dec 7 19:39:57.962624: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.962645: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.962700: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.962777: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.962797: player.c:470 decode_loop(): loop... Dec 7 19:39:57.963246: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.963267: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.963286: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.963385: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.963406: player.c:470 decode_loop(): loop... Dec 7 19:39:57.963856: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.963877: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.963896: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.963967: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.963987: player.c:470 decode_loop(): loop... Dec 7 19:39:57.964435: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.964455: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.964475: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.964545: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.964565: player.c:470 decode_loop(): loop... Dec 7 19:39:57.965013: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.965033: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.965053: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.965123: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.965143: player.c:470 decode_loop(): loop... Dec 7 19:39:57.965629: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.965652: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.965671: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.965742: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.965762: player.c:470 decode_loop(): loop... Dec 7 19:39:57.966209: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.966230: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.966250: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.966320: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.966340: player.c:470 decode_loop(): loop... Dec 7 19:39:57.966787: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.966808: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.966827: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.966898: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.966917: player.c:470 decode_loop(): loop... Dec 7 19:39:57.967364: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.967385: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.967404: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.967474: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.967494: player.c:470 decode_loop(): loop... Dec 7 19:39:57.967941: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.967962: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.967981: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.968052: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.968071: player.c:470 decode_loop(): loop... Dec 7 19:39:57.968518: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.968539: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.968558: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.968629: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.968648: player.c:470 decode_loop(): loop... Dec 7 19:39:57.969096: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.969117: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.969159: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.969231: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.969251: player.c:470 decode_loop(): loop... Dec 7 19:39:57.969698: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.969719: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.969738: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.969809: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.969828: player.c:470 decode_loop(): loop... Dec 7 19:39:57.970275: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.970295: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.970315: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.970385: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.970404: player.c:470 decode_loop(): loop... Dec 7 19:39:57.970852: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.970872: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.970891: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.970962: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.970981: player.c:470 decode_loop(): loop... Dec 7 19:39:57.971428: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.971449: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.971468: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.971538: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.971558: player.c:470 decode_loop(): loop... Dec 7 19:39:57.972006: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.972027: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.972046: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.972116: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.972137: player.c:470 decode_loop(): loop... Dec 7 19:39:57.972584: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.972605: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.972624: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.972723: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.972748: player.c:470 decode_loop(): loop... Dec 7 19:39:57.973196: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.973216: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.973236: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.973306: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.973326: player.c:470 decode_loop(): loop... Dec 7 19:39:57.973778: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.973800: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.973820: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.973891: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.973911: player.c:470 decode_loop(): loop... Dec 7 19:39:57.974370: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.974395: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.974414: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.974485: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.974505: player.c:470 decode_loop(): loop... Dec 7 19:39:57.974960: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.975022: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.975045: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.975122: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.975143: player.c:470 decode_loop(): loop... Dec 7 19:39:57.975624: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.975649: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.975670: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.975742: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.975762: player.c:470 decode_loop(): loop... Dec 7 19:39:57.976221: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.976243: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.976263: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.976333: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.976353: player.c:470 decode_loop(): loop... Dec 7 19:39:57.976801: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.976822: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.976841: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.976924: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.976945: player.c:470 decode_loop(): loop... Dec 7 19:39:57.977394: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.977415: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.977435: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.977505: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.977525: player.c:470 decode_loop(): loop... Dec 7 19:39:57.977974: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.977995: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.978014: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.978085: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.978105: player.c:470 decode_loop(): loop... Dec 7 19:39:57.978553: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.978574: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.978593: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.978664: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.978684: player.c:470 decode_loop(): loop... Dec 7 19:39:57.979131: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.979152: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.979172: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.979242: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.979262: player.c:470 decode_loop(): loop... Dec 7 19:39:57.979711: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.979732: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.979751: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.979822: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.979842: player.c:470 decode_loop(): loop... Dec 7 19:39:57.980289: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.980310: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.980330: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.980400: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.980453: player.c:470 decode_loop(): loop... Dec 7 19:39:57.980903: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.980924: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.980944: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.981015: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.981035: player.c:470 decode_loop(): loop... Dec 7 19:39:57.981506: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.981528: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.981547: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.981618: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.981638: player.c:470 decode_loop(): loop... Dec 7 19:39:57.982092: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.982119: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 1 because the bitrate hasn't changed Dec 7 19:39:57.982138: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.982210: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.982230: player.c:470 decode_loop(): loop... Dec 7 19:39:57.982776: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.982824: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.982846: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.982929: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.982951: player.c:470 decode_loop(): loop... Dec 7 19:39:57.983410: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.983434: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.983454: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.983525: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.983545: player.c:470 decode_loop(): loop... Dec 7 19:39:57.983995: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.984017: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.984036: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.984107: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.984126: player.c:470 decode_loop(): loop... Dec 7 19:39:57.984576: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.984597: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.984617: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.984687: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.984707: player.c:470 decode_loop(): loop... Dec 7 19:39:57.985155: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.985176: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.985195: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.985266: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.985286: player.c:470 decode_loop(): loop... Dec 7 19:39:57.985778: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.985803: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.985823: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.985894: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.985914: player.c:470 decode_loop(): loop... Dec 7 19:39:57.986363: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.986384: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.986403: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.986514: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.986535: player.c:470 decode_loop(): loop... Dec 7 19:39:57.986986: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.987011: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.987031: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.987106: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.987129: player.c:470 decode_loop(): loop... Dec 7 19:39:57.987599: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.987630: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.987653: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.987723: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.987744: player.c:470 decode_loop(): loop... Dec 7 19:39:57.988197: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.988225: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.988246: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.988318: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.988338: player.c:470 decode_loop(): loop... Dec 7 19:39:57.988805: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.988833: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.988853: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.988924: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.988945: player.c:470 decode_loop(): loop... Dec 7 19:39:57.989404: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.989436: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.989456: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.989527: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.989547: player.c:470 decode_loop(): loop... Dec 7 19:39:57.990005: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.990035: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.990059: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.990133: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.990154: player.c:470 decode_loop(): loop... Dec 7 19:39:57.990612: server.c:1723 server_loop(): accept()ing connection... Dec 7 19:39:57.990657: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.990683: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.990707: player.c:579 decode_loop(): putting into the buffer 9216 bytes Dec 7 19:39:57.990731: server.c:1730 server_loop(): Incoming connection Dec 7 19:39:57.990757: tags_cache.c:836 tags_cache_clear_queue(): Cleared requests queue for client 1 Dec 7 19:39:57.990781: audio_conversion.c:716 audio_conv(): Fast conversion! Dec 7 19:39:57.990803: player.c:470 decode_loop(): loop... Dec 7 19:39:57.990830: player.c:932 player_stop(): requesting stop Dec 7 19:39:57.990850: player.c:937 player_stop(): decoder_stream present, aborting... Dec 7 19:39:57.990868: io.c:266 io_abort(): Aborting... Dec 7 19:39:57.990891: io.c:273 io_abort(): done Dec 7 19:39:57.990921: server.c:1431 handle_command(): Client disconnected Dec 7 19:39:57.990950: io.c:434 io_read_thread(): Stop request Dec 7 19:39:57.990982: io.c:436 io_read_thread(): Exiting IO read thread Dec 7 19:39:57.991021: tags_cache.c:836 tags_cache_clear_queue(): Cleared requests queue for client 1 Dec 7 19:39:57.991280: player.c:511 decode_loop(): decoded 9216 bytes Dec 7 19:39:57.991304: player.c:188 bitrate_list_add(): Not adding bitrate 320 at time 2 because the bitrate hasn't changed Dec 7 19:39:57.991356: player.c:541 decode_loop(): stop Dec 7 19:39:57.991376: out_buf.c:322 out_buf_stop(): stopping the buffer Dec 7 19:39:57.991395: out_buf.c:327 out_buf_stop(): sending signal Dec 7 19:39:57.991413: out_buf.c:329 out_buf_stop(): waiting for signal Dec 7 19:39:58.081251: alsa.c:544 play_buf_chunks(): Played 14400 bytes Dec 7 19:39:58.081334: alsa.c:548 play_buf_chunks(): 576 bytes remain in alsa_buf Dec 7 19:39:58.081355: alsa.c:613 alsa_play(): Played everything Dec 7 19:39:58.082252: out_buf.c:331 out_buf_stop(): done Dec 7 19:39:58.082282: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:58.082318: io.c:284 io_close(): Closing stream... Dec 7 19:39:58.082340: io.c:291 io_close(): Waiting for io_read_thread()... Dec 7 19:39:58.082362: io.c:293 io_close(): IO read thread exited Dec 7 19:39:58.082389: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:58.082586: io.c:344 io_close(): done Dec 7 19:39:58.082611: player.c:141 bitrate_list_empty(): Bitrate list elements removed. Dec 7 19:39:58.082633: out_buf.c:417 out_buf_wait(): Waiting for read thread to suspend... Dec 7 19:39:58.082652: out_buf.c:426 out_buf_wait(): done Dec 7 19:39:58.082732: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:58.082756: player.c:901 player(): exiting Dec 7 19:39:58.082776: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:58.082798: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:58.082820: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:58.082846: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:58.082876: audio.c:377 go_to_another_file(): Playing next... Dec 7 19:39:58.082896: audio.c:398 go_to_another_file(): End of the list Dec 7 19:39:58.082918: server.c:257 wake_up_server(): Waking up the server Dec 7 19:39:58.082944: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:58.082972: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:58.082994: server.c:667 send_events(): Flushing events for client 0 Dec 7 19:39:58.083022: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:58.083046: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:58.083069: server.c:1738 server_loop(): Got 'wake up' Dec 7 19:39:58.083521: alsa.c:580 alsa_close(): ALSA device closed Dec 7 19:39:58.083545: audio.c:490 play_thread(): Exiting

tomaszg

Wed, 2016-12-07 19:40

Can't find anything suspicious here. Looks like MOC really reached the end of the playlist. Especially since the problem appears only with the Python script, I would guess that the problem is in the script itself.

It's quite hard to debug by remote ;) Maybe you could try logging all executed MOC commands to a file and see that nothing suspicious is getting started? If this script is not very tightly tied to RPi, maybe you could try to run it on normal machine? Or even post it here for other people to look at it? (BTW. pastebin is a good thing ;) ).

RasPi

Wed, 2016-12-07 20:03

Well, it's just a python script :)
Maybe you can find anything - seems like I'm blind in the meanwhile.

Script to start Moc on boot

#!/usr/bin/env python import sys import logging import time import subprocess import select # see http://stackoverflow.com/a/10759061/3761783 import os import signal, errno SOUND_CONFIRM = "/home/pi/Musik/jukeboxsounds/confirm.mp3" # Start mocp subprocess.call(["sudo","-u", "pi", "mocp", "--server"]) #subprocess.call(["sudo","-u", "pi", "mocp", "-D"]) subprocess.call(["sudo","-u", "pi", "mocp", "--clear"]) subprocess.call(["sudo","-u", "pi", "mocp", "-l", SOUND_CONFIRM])

Script to control mocp

#!/usr/bin/env python3 import sys import logging import time import subprocess import select # see http://stackoverflow.com/a/10759061/3761783 import os import signal, errno # Values --------------------- # SOUND_SCANNING = "/home/pi/Musik/jukeboxsounds/scanning.mp3" SOUND_TIMEOUT = "/home/pi/Musik/jukeboxsounds/error_wawawaaa.mp3" SOUND_ERROR = "/home/pi/Musik/jukeboxsounds/timeout_error.mp3" SOUND_CONFIRM = "/home/pi/Musik/jukeboxsounds/confirm.mp3" QR_SCANNER_TIMEOUT = 5 # ---------------------------- # # get parameter from 'remote.sh' remote = sys.argv[1] # control moc matching remote control if (remote == 'next'): print('Next') subprocess.call(["sudo", "mocp", "--next"]) if (remote == 'prev'): print('Previous') subprocess.call(["sudo", "mocp", "--previous"]) if(remote == 'play'): print('Pause/Play') subprocess.call(["sudo", "mocp", "--toggle-pause"]) # Scan QR Code and start playback if code is recognized, otherwise play error sound if (remote == 'power'): # Play scanning sound subprocess.call(["sudo", "mocp", "--clear"]) subprocess.call(["sudo", "mocp", "-l", SOUND_SCANNING]) time.sleep(3) print("start scanning") # scan QR code zbarcam = subprocess.Popen(['zbarcam', '--nodisplay', '--raw', '-Sdisable', '-Sqrcode.enable', '--prescale=320x240', '/dev/video0'], stdout=subprocess.PIPE, stderr=subprocess.PIPE) poll_obj = select.poll() poll_obj.register(zbarcam.stdout, select.POLLIN) # wait for scan result (or timeout) start_time = time.time() poll_result = False while ((time.time() - start_time) < QR_SCANNER_TIMEOUT and (not poll_result)): poll_result = poll_obj.poll(100) print("start analysis") if (poll_result): try: qr_code = zbarcam.stdout.readline().rstrip() qr_code = qr_code.decode("utf-8") if(qr_code != ""): print("qr code erkannt " + qr_code) subprocess.call(["sudo", "mocp", "--clear"]) # play confirmation sound print("play confirmation") subprocess.call(["sudo", "mocp", "-l", SOUND_CONFIRM]) subprocess.call(["sudo", "mocp", "--clear"]) time.sleep(2) subprocess.check_call(["sudo", "mocp", "-a", qr_code]) subprocess.check_call(["sudo", "mocp", "-p"]) else: print("QR Code not recognized") subprocess.call(["sudo", "mocp", "-l", SOUND_TIMEOUT]) time.sleep(1) except subprocess.CalledProcessError as e: print("Error - play error sound") subprocess.call(["sudo", "mocp", "-l", SOUND_ERROR]) time.sleep(1) except FileNotFoundError as e: print("FError - play error sound") subprocess.call(["sudo", "mocp", "-l", SOUND_ERROR]) time.sleep(1) else: print("Timeout - play timeout sound) subprocess.call(["sudo", "mocp", "-l", SOUND_TIMEOUT]) time.sleep(1) zbarcam.terminate()

tomaszg

Wed, 2016-12-07 22:46

I didn't read it very carefully (I don't know Python) - however it was pointed out to me that your init script runs MOC as user "pi", while the other runs it as "root". They are separate MOC instances and that might mess things up a bit due to some unexpected interaction.

However I don't really follow how that would produce errors you described. Only root version of MOC gets controlled with the second script so, both playlist reading and next/prev commands are set to the same instance. Do those users share some directories, like ~/.moc? Moreover if you started pi-instance with -D, why it received "next" command? I'm a bit puzzled and it's getting too late here for me to focus right now ;)

RasPi

Mon, 2016-12-12 06:45

I had some Copy-Paste errors in my script - sorry for that :-(
My "original" script in the meanwhile is full of out-commented code - this is what I didn't want you to read.

I tried to run it with different "test data", this time a radio play of my daughter, and i figured out whats happening with Moc:

I start playback and press randomly previous / next on my remote. Mostly Moc steps to the next track or steps back to the previous one. But sometimes the player skips one or more tracks.

Controlling Moc with console this behavior doesn't appear.

So last thing could be the remote - maybe a button is pressed too long and the command is sent multiple times to the player. I inserted console prints: each button press causes one console print. So what do you think, is it really the remote?!

jcf

Tue, 2016-12-13 20:12

I can see several possibilities here, but before we can help you any further we really need to know which release of MOC you are using.

RasPi

Wed, 2016-12-14 21:20

Hi,
sorry...do you need any other information?

This is : Music On Console Version : 2.5.0 Revision : 2668 Built : Sep 13 2014 08:08:23 Compiled with : OSS ALSA JACK DEBUG Network streams resample Running on : Linux 4.4.26-v7+ armv7l Author : Damian Pietras Homepage : http://moc.daper.net/ E-Mail : mocmaint@daper.net Copyright : (C) 2003-2014 Damian Pietras and others License : GNU General Public License, version 2 or later

jcf

Wed, 2016-12-14 22:11

Okay, so that eliminates the most likely cause of what you're seeing as it was already fixed in MOC 2.5.0.

But that release is quite old now and there have been many bugs fixed since then. Are you able to try the latest 2.5 version (released as 2.5.2), or even the most recent release (2.6-alpha3)?

I noted from the log you posted that the audio you are trying to play appears to be sub-second in duration. Is that what you are expecting?

Is it possible you're just not hearing that short an audio? (We know that the RPi has some problems with audio, but if you're hearing it when driving from the command line but not your script then that implies not... but does imply the problem lies in the script.)

RasPi

Thu, 2016-12-15 21:25

So in the meanwhile my main problem is that the options Next, Previous and Mute via Remote Control don't work as expected.

I'm not sure if that is really a problem of Lirc, my remote or my script because if I just give a print on console after pressing the remote I just receive one line for each button press. Otherwise, if I control Moc just via console commands Moc works fine... :-(

Sure, I'd like to update - but how? sudo apt-get upgrade tells me that Moc v.2.5.0 is already the latest version.

tomaszg

Fri, 2016-12-16 04:00

If your distribution doesn't provide newer Moc, all you can do is to try to compile it from the source.

jcf

Fri, 2016-12-16 10:03

... ask the MOC package maintainer for that repository to upgrade.

jcf

Sat, 2016-12-17 07:08

From your code (and it's not clear if that posted may contain cut and paste errors), when a new QR code is scanned you clear the playlist, add the new audio then start it playing. At any one time, there is only one item in the playlist so 'next' and 'previous' will cause MOC to stop playing.

You may also want to consult the configuration file's SyncPlaylist option as different clients can maintain distinct playlists and it may be this which is confusing you when a console client is also active.

As for play/pause, that may be a separate issue but let's tackle the next/previous one and the playlists first then see if it still exists.

jcf

Sun, 2016-12-18 20:03

Is it possible that you have multiple instances of your script running? If there were two (or more) instances listening for and actioning the same interface signals then it would account for several of your observations.

An even number of instances each toggling pause would cancel each other out. If there were two instances each actioning a 'next', then the server would skip one playlist entry (although it's not clear how you would actually get multiple playlist entries in the first place, unless there's something you're not telling us about what the QR code represents).

tliero

Fri, 2016-12-30 06:25

Hey there,
are you sure that this is a sound file that's being played and not just the infamous crackling noise on the RasPi?
I've built a similar player - which you might be aware of, since some of that code looks quite familiar ;) - and ran into similar problems. (Wrote about audio problems with moc and the RasPi here in German.)
I've solved them by using PusleAudio. Unfortunately, you will either have to recompile mocp to support that sound system or use the PulseAudio wrapper (which is an easier but less elegant solution).

In order to run with PulseAudio, the OSS sound driver has to be set as first option in ~/.moc/config. The mocp server is then started over the padsp wrapper with padsp mocp --server

Anyway, I'm currently building my second player and can recommend the PHAT DAC extension from Pimoroni. This removes the headaches with all of the audio and provides much better sound as the original RasPi. So if that is an option for you, I'd say go for it.

jcf

Thu, 2017-02-02 00:59

Despite our attempts to help him, the OP has disengaged without explanation.

I'm pretty sure this is not a MOC problem, but I guess we'll never know.