Bugzilla – Bug 7427
transporter cold-reboots (or fully hangs) when playing wma radio stream
Last modified: 2012-02-27 17:33:28 UTC
I have recently came across one wma stream, that causes transporter to cold-reboot (as if pressing and holding power button) or irrecoverably hang (led blanks, audio stops as if no server and doesn't respond to any buttons), so that only disconnecting power source helps get it back to life. It plays the stream fine fine for 10-15 minutes, then reboots or hangs. What do I need to turn on to debug this? Here's my system info: SqueezeCenter Version: 7.0 - 17610 - Mac OS X 10.5.2 (9C31) - EN - utf8 Server IP address: 192.168.11.2 Perl Version: 5.8.8 darwin-thread-multi-2level MySQL Version: 5.0.22-standard Platform Architecture: x86 Hostname: macbook-3.local Server Port Number: 9000 Total Players Recognized: 1 Player Information Name: Eugene's Model: transporter Firmware: 36 The IP address for this player is: 192.168.11.6:25011 The ethernet MAC address for this player is: 00:04:20:10:05:5d Voltage: 230 Thanks, Eugene
Would you mind sharing the particular stream?
I'm sorry, I forgot to paste it while describing the problem. Here it is: mms://wma.nashe.ru:80/Nashe128
Are there any other networking issues during the hang? Any issues with your router? Re: logging try network.protocol.slimproto
While the station is playing, it may (but not always) pause for re-buffering and then continue playing (like insuffucient internet connection speed). Router doesn't appear to hang or reboot -- the internet connections keeps working for other computers. There's one more thing -- I think it maybe somehow linked to this issue: I had two radiostations (this time in mp3 shoutcast format) that play fine from the beginning, but in 5-10-15 minutes (it's usually different) may start sound like stream went out of sync (e.g. "fast-forward" was turned on, but with accidential clicks and pops). After playing such "broken" stream for a minute or two, Transporter pauses and starting to rebuffer the stream, but once it resumes playing it is still sounds exactly the same -- like "out of sync" and "fast-forward", then pauses, re-buffering, playing the same & etc. Never stops. Re-connecting to the same stream (via remote or via squeezecenter) resolves the issue, but it may appear again in 5-10-15 minutes. The url for the such stream is http://mp3.nashe.ru/nashe-192 This problem made me find WMA stream of the that particular station, but WMA stream that I have found mms://wma.nashe.ru:80/Nashe128 now causes Transporter to reboot! Later today I will try to turn logging on as you described and send you the results. If I finds another router, I'll try changing it too. Thanks, Eugene
I am able to play mms://wma.nashe.ru:80/Nashe128 without Transporter rebooting. The station does rebuffer quite a bit however but does come back. I did notice that you are running a slightly older version of SqueezeCenter and suggest you update to the final 7 version. You might want to try playing the station through SqueezeCenter and see if you get the same behavior. Another thing you may wish to try but is probably a long shot is to factory reset your unit and reset the Xilinx. Instruction on how to do this is here: http://wiki.slimdevices.com/index.cgi?PlayerFirmware
Steven, how long did have you been playing the station with TP? This time TP rebooted after 29 minutes of playing Before this test, I updated the squeezecenter as recommended, however it did not help. Here is network.protocol log. TP rebooted at 23:35 -- 23:36. [23:35:00.4127] Slim::Networking::Slimproto::client_readable (368) Slimproto frame: STAT, len: 55 [23:35:00.4139] Slim::Networking::Slimproto::_stat_handler (721) 00:04:20:10:05:5d Squeezebox stream status: event_code: STMt bytes_rec_H 0 bytes_rec_L 27827541 fullness: 63338 (2%) bufferSize 3145728 fullness 63338 bytes_received 27827541 signal_strength: 65535 jiffies: 140923931 [23:35:00.4142] Slim::Networking::Slimproto::_stat_handler (733) output size: 3528000 output fullness: 3526400 elapsed seconds: 1713 [23:35:00.4145] Slim::Networking::Slimproto::_stat_handler (745) elapsed milliseconds: 1713182 server timestamp: 0 [23:35:01.4366] Slim::Networking::Slimproto::client_readable (368) Slimproto frame: STAT, len: 55 [23:35:01.4372] Slim::Networking::Slimproto::_stat_handler (721) 00:04:20:10:05:5d Squeezebox stream status: event_code: STMt bytes_rec_H 0 bytes_rec_L 27835963 fullness: 56278 (1%) bufferSize 3145728 fullness 56278 bytes_received 27835963 signal_strength: 65535 jiffies: 140924931 [23:35:01.4374] Slim::Networking::Slimproto::_stat_handler (733) output size: 3528000 output fullness: 3519232 elapsed seconds: 1714 [23:35:01.4376] Slim::Networking::Slimproto::_stat_handler (745) elapsed milliseconds: 1714182 server timestamp: 0 [23:35:02.4597] Slim::Networking::Slimproto::client_readable (368) Slimproto frame: STAT, len: 55 [23:35:02.4604] Slim::Networking::Slimproto::_stat_handler (721) 00:04:20:10:05:5d Squeezebox stream status: event_code: STMt bytes_rec_H 0 bytes_rec_L 27835963 fullness: 41820 (1%) bufferSize 3145728 fullness 41820 bytes_received 27835963 signal_strength: 65535 jiffies: 140925931 [23:35:02.4607] Slim::Networking::Slimproto::_stat_handler (733) output size: 3528000 output fullness: 3524352 elapsed seconds: 1715 [23:35:02.4610] Slim::Networking::Slimproto::_stat_handler (745) elapsed milliseconds: 1715182 server timestamp: 0 [23:35:03.3814] Slim::Networking::Slimproto::client_readable (368) Slimproto frame: STAT, len: 55 [23:35:03.3821] Slim::Networking::Slimproto::_stat_handler (721) 00:04:20:10:05:5d Squeezebox stream status: event_code: STMt bytes_rec_H 0 bytes_rec_L 27843263 fullness: 31590 (1%) bufferSize 3145728 fullness 31590 bytes_received 27843263 signal_strength: 65535 jiffies: 140926931 [23:35:03.3824] Slim::Networking::Slimproto::_stat_handler (733) output size: 3528000 output fullness: 3521280 elapsed seconds: 1716 [23:35:03.3827] Slim::Networking::Slimproto::_stat_handler (745) elapsed milliseconds: 1716182 server timestamp: 0 [23:35:04.0008] Slim::Networking::Slimproto::check_all_clients (198) Checking if 00:04:20:10:05:5d is still alive [23:35:04.0016] Slim::Player::Squeezebox::stream (805) stream called: t paused: undef format: undef url: undef [23:35:04.0020] Slim::Player::Squeezebox::stream (811) Backtrace: frame 0: Slim::Player::Squeezebox::__ANON__ ((eval 942) line 17) frame 1: Log::Log4perl::Logger::__ANON__ (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/CPAN/Log/Log4perl/Logger.pm line 771) frame 2: Log::Log4perl::Logger::__ANON__ (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Player/Squeezebox.pm line 811) frame 3: Slim::Player::Squeezebox::stream (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Player/Squeezebox2.pm line 231) frame 4: Slim::Player::Squeezebox2::requestStatus (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Networking/Slimproto.pm line 220) frame 5: Slim::Networking::Slimproto::check_all_clients (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Utils/Timers.pm line 198) frame 6: (eval) (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Utils/Timers.pm line 198) frame 7: Slim::Utils::Timers::checkTimers (./slimserver.pl line 506) frame 8: main::idle (./slimserver.pl line 453) frame 9: main::main (./slimserver.pl line 1005) [23:35:04.0026] Slim::Player::Squeezebox::stream (1088) Starting with decoder with format: m autostart: 1 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ? [23:35:04.0029] Slim::Player::Squeezebox::stream (1121) flags: 0 [23:35:04.0032] Slim::Player::Squeezebox::stream (1147) sending strm frame of length: 24 request string: [] [23:35:04.0035] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: strm, length: 24 [23:35:09.0088] Slim::Networking::Slimproto::check_all_clients (198) Checking if 00:04:20:10:05:5d is still alive [23:35:09.0095] Slim::Player::Squeezebox::stream (805) stream called: t paused: undef format: undef url: undef [23:35:09.0099] Slim::Player::Squeezebox::stream (811) Backtrace: frame 0: Slim::Player::Squeezebox::__ANON__ ((eval 942) line 17) frame 1: Log::Log4perl::Logger::__ANON__ (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/CPAN/Log/Log4perl/Logger.pm line 771) frame 2: Log::Log4perl::Logger::__ANON__ (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Player/Squeezebox.pm line 811) frame 3: Slim::Player::Squeezebox::stream (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Player/Squeezebox2.pm line 231) frame 4: Slim::Player::Squeezebox2::requestStatus (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Networking/Slimproto.pm line 220) frame 5: Slim::Networking::Slimproto::check_all_clients (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Utils/Timers.pm line 198) frame 6: (eval) (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Utils/Timers.pm line 198) frame 7: Slim::Utils::Timers::checkTimers (./slimserver.pl line 506) frame 8: main::idle (./slimserver.pl line 453) frame 9: main::main (./slimserver.pl line 1005) [23:35:09.0103] Slim::Player::Squeezebox::stream (1088) Starting with decoder with format: m autostart: 1 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ? [23:35:09.0105] Slim::Player::Squeezebox::stream (1121) flags: 0 [23:35:09.0108] Slim::Player::Squeezebox::stream (1147) sending strm frame of length: 24 request string: [] [23:35:09.0111] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: strm, length: 24 [23:35:14.0007] Slim::Networking::Slimproto::check_all_clients (198) Checking if 00:04:20:10:05:5d is still alive [23:35:14.0014] Slim::Player::Squeezebox::stream (805) stream called: t paused: undef format: undef url: undef [23:35:14.0019] Slim::Player::Squeezebox::stream (811) Backtrace: frame 0: Slim::Player::Squeezebox::__ANON__ ((eval 942) line 17) frame 1: Log::Log4perl::Logger::__ANON__ (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/CPAN/Log/Log4perl/Logger.pm line 771) frame 2: Log::Log4perl::Logger::__ANON__ (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Player/Squeezebox.pm line 811) frame 3: Slim::Player::Squeezebox::stream (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Player/Squeezebox2.pm line 231) frame 4: Slim::Player::Squeezebox2::requestStatus (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Networking/Slimproto.pm line 220) frame 5: Slim::Networking::Slimproto::check_all_clients (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Utils/Timers.pm line 198) frame 6: (eval) (/Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/Slim/Utils/Timers.pm line 198) frame 7: Slim::Utils::Timers::checkTimers (./slimserver.pl line 506) frame 8: main::idle (./slimserver.pl line 453) frame 9: main::main (./slimserver.pl line 1005) [23:35:14.0023] Slim::Player::Squeezebox::stream (1088) Starting with decoder with format: m autostart: 1 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ? [23:35:14.0027] Slim::Player::Squeezebox::stream (1121) flags: 0 [23:35:14.0030] Slim::Player::Squeezebox::stream (1147) sending strm frame of length: 24 request string: [] [23:35:14.0034] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: strm, length: 24 [23:35:18.3355] Slim::Networking::Slimproto::slimproto_accept (176) Accepted connection from: [192.168.11.6:24043] [23:35:18.3359] Slim::Networking::Slimproto::slimproto_accept (179) Setting timer in 5 seconds to close bogus connection [23:35:18.3468] Slim::Networking::Slimproto::client_readable (368) Slimproto frame: HELO, len: 36 [23:35:18.3472] Slim::Networking::Slimproto::_hello_handler (840) Killing bogus player timer. [23:35:18.3477] Slim::Networking::Slimproto::_hello_handler (874) Squeezebox says hello: Deviceid: 5 revision: 36 mac: 00:04:20:10:05:5d uuid: 00000000000000000000000000000000 bitmapped: 32768 reconnect: 0 wlan_channellist: 0000 [23:35:18.3479] Slim::Networking::Slimproto::_hello_handler (885) Squeezebox also says: bytes_received: 0 [23:35:18.3484] Slim::Networking::Slimproto::_hello_handler (1016) Hello from existing client: 00:04:20:10:05:5d on ipport: 192.168.11.6:24043 [23:35:18.3487] Slim::Networking::Slimproto::_hello_handler (1022) Closing previous socket to client: 00:04:20:10:05:5d on ipport: 192.168.11.6:37928 [23:35:18.3490] Slim::Networking::Slimproto::slimproto_close (231) connection closed [23:35:18.3502] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: grfb, length: 2 [23:35:18.3513] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: grfe, length: 1284 [23:35:18.3519] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: grfe, length: 1284 [23:35:18.3531] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: grfe, length: 1284 [23:35:18.3539] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: visu, length: 2 [23:35:18.3543] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: setd, length: 1 [23:35:18.3546] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: setd, length: 1 [23:35:18.3550] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: setd, length: 1 [23:35:18.3554] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: setd, length: 1 [23:35:18.3557] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: setd, length: 1 [23:35:18.3560] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: audc, length: 1 [23:35:18.3565] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: knob, length: 14 [23:35:18.3776] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: aude, length: 2 [23:35:18.3785] Slim::Player::Squeezebox::sendFrame (1211) sending squeezebox frame: audg, length: 18 [23:35:18.3795] Slim::Networking::Slimproto::client_readable (368) Slimproto frame: STAT, len: 55 [23:35:18.3801] Slim::Networking::Slimproto::_stat_handler (721) 00:04:20:10:05:5d Squeezebox stream status: event_code:
Created attachment 3044 [details] complete log for times 23:35 to 23:36 when Transporter reboot occured network.protocol.slimproto turned to debug level. Rebooted at 23:35 - 23:36
I was able to play the station for over an hour. After about an hour however the rebuffering got so bad that Transporter went into a pause state but did not reboot. Hopefully the log will reveal something.
I wonder if Felix has any ideas how we might simulate a really really laggy stream.
Created attachment 3046 [details] network.protocol.slimproto log this is log for 9:42 to 9:44
Some more details: Steven, how was your TP connected, wireless or wired conection? I am running Transporter over a wired ethernet connection. To see if the reboot-issue is somehow router and connection-related, I have connected Transporter via wireless connection and different router. The station plays for some time (5 to 10 minutes), rebuffers maybe once and then just stops playing (no idea why). However, the no reboot is happening, which is similar to Steven's TP behaviour. I have enclosed the networ.protocol.climpro log for this case "network.protocol.slimpro log" Thanks, Eugene
Something you can try in the meantime is to turn on 'Proxied Streaming' option under 'Player Settings' 'Audio' and see if the performance is improved.
Please see bug 3383, as this appears to be a duplicate of that bug *** This bug has been marked as a duplicate of 3383 ***
I am sorry, but I do not agree that this is a duplicate of bug 3383: in my case, the station plays fine for certain amount of time (e.g. 30 minutes, but it always varies) then it makes the TP to cold-reboot. The problem described in bug 3383 refers to mms streams that do not have http equivalents, which it completely different from the situation I have described. Further to the case: as prescribed, have turned proxied streaming on. Which appears to not to reboot the TP while playing the stream, however it just stops playing after some time. I will play with it for some more time to see if proxied streaming helps. Any other options to try or logging to turn on? Eugene
Eugene: Try turning on the following options to see if they improve the quality of the stream Settings > Advanced > Network > Radio Station Timeout from 5 to 30 When I did this, the steam played for me with no errors for 58 minutes, then stopped. It did this 6 times, so I'm guessing that the stream has a time limit associated with it. ------------- Also, have you seen this problem with other MMS streams from .RU or just this one? I have tested a few other Russian streams and haven't seen the problem yet. I have tried the following: MMS://steam.rfn.ru/cultradio RadioTime > Europe > Russia > Moskva > M-Radio 96.4 If you have been able to see this problem with other streams, please let me know which ones so I can add them to my testing. ------------- Have you tried to reproduce this using the Soft Squeeze player or a SB2/3 (if you have one)?
To make sure we're working on the same problem which is about Transporter COLD-REBOOTING all of a sudden while playing the stream. By "cold-reboot" I mean the same behaviour as if TP has just been removed from power plug and then plugged back -- with audible relay clicks and booting process. Another problem of Transporter stopping playing the stream could be relevant, but secondary. As it may easily be dependable on the broadcasting server settings and out of our control... Anyway, I'll perform the adjustments and try other similar streams to see if the TP behaviour is the same. Thanks, Eugene
Eugene Have you had a chance to look into this any more have you had any issues with other streams?
I have upgraded to latest SC and Transporter firmware (40). I had limited time to continuosly listen to both streams for no more than an hour (breakfast time :-) before running to office) and ao far I didn't experience any reboots. Give me some more time -- Easter holidays are coming, so I'll spend more time at home and will try to listen for more to get more reliable feedback. Thanks, Eugene
Please test with latest 7.0.1.
Sorry it took longer to test it. Transporter still reboots when playing WMA stream :(. Sometimes it just stops, but sometimes reboots after loud click. You never know what will happen next, but it is easily reproducable. If needed, let me know which logging to turn on. Last time I tested it with: SqueezeCenter Information SqueezeCenter Version: 7.0.1 - 18463 @ Sun Apr 6 00:16:40 PDT 2008 - Mac OS X 10.5.2 (9C7010) - EN - utf8 Server IP address: 192.168.11.3 Perl Version: 5.8.8 darwin-thread-multi-2level MySQL Version: 5.0.22-standard Platform Architecture: x86 Hostname: macbook-5.local Server Port Number: 9000 Total Players Recognized: 1 Player Information Name: Eugene's Model: transporter Firmware: 37 The IP address for this player is: 192.168.11.2:47539 The ethernet MAC address for this player is: 00:04:20:10:05:5d Voltage: 115 Eugene
Andy thinks a change that was put in last week should improve this behavior.
allright, i'll try downloading tonight's build
Any news, Eugene?
sorry for delay. today downloaded latest version of squeee center. Played ok for a while, rebuffered with no problem couple of times, then stopped, not rebooted nor hanged. I used remote to go to favourites menu to start the station playing again (TP responded and changed the menus on the screen but I didn't make to the right menu when TP cold-rebooted. I have to say it only happens with that particular wma stream and never with anything else -- flac or mp3 music, shoutcast radio Eugene
Steven to see if this still happens.
Still not able to reproduce. Changing target to monitor for now. Eugene, are you still able to reproduce? Have you experienced the issue with any other station?
ok, i'll download latest verision of sc and try it out.
*** Bug 8054 has been marked as a duplicate of this bug. ***
Here is my current set-up. The issue appears to be gone -- it plays wma stream in question without rebooting. Version: 7.3 - 23935 @ Sat Nov 15 03:00:49 PST 2008 Hostname: macbook-242.local Server IP Address: 192.168.11.3 Server HTTP Port Number: 9000 Operating system: Mac OS X 10.5.5 (9F33) - EN - utf8 Platform Architecture: x86 Perl Version: 5.8.8 - darwin-thread-multi-2level MySQL Version: 5.0.22-standard Total Players Recognized: 1 Library Statistics Total Tracks: 2,535 Total Albums: 217 Total Artists: 221 Total Genres: 48 Total Playing Time: 233:56:26 Music Scan Details Artwork Scan (1 of 1) Complete 00:00:00 SqueezeCenter has finished scanning your music collection. Total Time: 00:00:00 (Saturday, December 13, 2008 / 23:29) Player Information Information on all identified devices connected to SqueezeCenter Eugene's Player Model: transporter Firmware: 69 Player IP Address: 192.168.11.5 Player MAC Address: 00:04:20:10:05:5d Voltage: 115
Closing resolved bugs - if you feel this bug still exists please first re-test with the latest SW/FW version. If you are able to reproduce then feel free to reopen and attach new logs / steps to reproduce.