Bugzilla – Bug 1634
SlimScrobbler causes Slimserver crash while playing
Last modified: 2008-12-15 13:06:41 UTC
SlimServer crashed quite a few times this weekend using the last 2 nightlies.(4th/5th June). Ran with logging and the next crash gave this error: EOF instead of response status line at /PerlApp/Net/HTTP/Methods.pm line 300. ...propagated at /PerlApp/Net/HTTP/NB.pm line 32. File playing was AAC (.m4a) but can't be sure it was every time.
anything more than this when using --diag in the command line? some http response is coming back empty. hard to see how this occurs with playback. is it ONLY while playing? could it be a scrobbler submission, biography, or rss plugin response error?
It could be the scrobbler plugin, that's the only one I have active which accesses the net. I don't use SlimServer much during the week but will try the --diag flag.
is there a bug number for the http problem you refer to - I think I am still hitting it - cannot find with search...
the http bug I'm referring to is this one :) the lines you report from the log are part of the Net::HTTP package and appear to be part of a get request. Due to being external modules, they do not have the usual slimserver debug output. This line in Methods.pm in particular is the result of a 'die' call when some sort of response comes back undefined. I'm hoping --diag will give more of a backtrace from 'die'.
I'm seeing this very crash message as a result of SlimScrobbler 0.30 It may be a leap...but I'd guess SlimScrobbler is once again broken
Has this been reported to Stewart, the SlimScrobbler author?
Stewart didn't do this release, and this bug report was only linked to slimscrobbler 4 hours ago :) I'm not sure who to contact this time, especially given that the last note I sent regarding lack of proxy support was ignored (or at least regressed out when lwp was no longer used).
I have posted to the plugins forum on this. I've also tested now with mandrake 10.1, svn rev 3356 and it seems all is well there. This might just be windows related...or perhaps an intermittent problem from the scrobbler server response.
I believe this is related to SlimScrobbler - I saw it once while putting together ss v.30. Unfortunately I couldn't recreate it, so I put it down to transient weirdness from AudioScrobbler. Any suggestions as to how I could catch this in the SlimScrobbler code?
I'll attach a patch shortly to add some backtrack and a dump where the crash occurs. Maybe the data will mean more to you than myself. I've also patched two lines in teh main plugin module, since the current commands are slated for removal after SlimServer 6.1
Created attachment 539 [details] patch for test
Created attachment 540 [details] log from test win2k, slimserver 6.1, slimscrobbler 0.30. The last symbol reference is a mystery to me.
retitling for later reference.
Pushing this out. Will revisit if there's an issue in SlimServer to be fixed for 6.1.
vidur, is it possible that your fix at change 3396 would be referring to the same kind of crash mentioned here? I suspected it was a timeout from the scrobbler server, so your comments made me think of this.
kdf, I've reviewed vidur's fix, and it looks like it should work on slimscrobbler too. I'll make a similar change to the slimscrobbler code over the next couple of days (sorry to have been a little slow getting to this). Are you able to recreate this problem on demand? As you were able to obtain that log I wonder if you've some way of triggering it. If so, could I get you to test the fix when I put it in? (Actually, this is in a piece of code in SlimScrobbler that does much the same as the AsyncHTTP stuff in the slimserver. Long term I'd like to take all of this out of SlimScrobbler and use AsyncHTTP instead, but that's not going to happen very soon) I'll also change the callback set/clear stuff, thanks for that. Cheers, Ian
Its very repeatable on one of my setups, so no problem testing when you get a chance. Most times on my windows setup, it will crash right on the first handshake. Let me know when you have a fix in your cvs and I'll give it a go.
kdf, I've put the fix up in the slimscrobbler CVS, can you give it a whirl? (Give sourceforge a couple of hours to mirror the anonymous access CVS) I've also put proxy support in, which I think was something you needed? If you could test that I'd appreciate it, as I don't have a local proxy handy. It should just pick up your webproxy setting and use it. Thanks, Ian
well, took a long time for sf to update anonymous. I loaded up and it didn't crash, but didn't fully work either. Strangely, the user and password ARE set properly in the prefs. Here is the log, minus the HUGE list of backlogged tracks: 2005-06-16 19:57:01.0538 RSS Feed Info: 2005-06-16 19:57:01.0541 BBC News World Edition, http://news.bbc.co.uk/rss/newsonline_world_edition/front_page/rss091.xml 2005-06-16 19:57:01.0543 CNET News.com, http://news.com.com/2547-1_3-0-5.xml 2005-06-16 19:57:01.0544 New York Times Home Page, http://www.nytimes.com/services/xml/rss/nyt/HomePage.xml 2005-06-16 19:57:01.0546 RollingStone.com Music News, http://www.rollingstone.com/rssxml/music_news.xml 2005-06-16 19:57:01.0547 Slashdot, http://slashdot.org/index.rss 2005-06-16 19:57:01.0549 Yahoo! News: Business, http://rss.news.yahoo.com/rss/business 2005-06-16 19:57:01.0551 2005-06-16 19:57:01.0554 hookScrobbler() engaged, SlimScrobbler V0.31 activated. 2005-06-16 19:57:02.9531 Creating new PlayerStatus for 10.6.1.80 (f0:5a:f4:24:93:98) 2005-06-16 19:57:02.9537 Using default User/password (10.6.1.80) 2005-06-16 19:57:02.9540 User ID: kevindf 2005-06-16 19:57:02.9543 Creating new Session for kevindf 2005-06-16 19:57:02.9545 ==Session.new 2005-06-16 19:57:02.9549 ==BackgroundHTTP.new 2005-06-16 19:57:11.0583 It IS time to submit! 2005-06-16 19:57:11.0587 About to attempt submit to Audioscrobbler.. 2005-06-16 19:57:11.0589 ==doBackgroundHandshakeThenSubmit 2005-06-16 19:57:11.0592 Firing GET on URL: http://post.audioscrobbler.com/?hs=true&p=1.1&c=slm&v=0.31&u=kevindf 2005-06-16 19:57:11.0595 ==BackgroundHTTP.get 2005-06-16 19:57:11.0609 Using proxy 10.6.1.254:8080 2005-06-16 19:57:11.0614 Clearing DNS cache 2005-06-16 19:57:11.0618 10.6.1.254 is already resolved 2005-06-16 19:57:11.0620 Connecting to 10.6.1.254:8080 2005-06-16 19:57:11.0666 Connected. Sending request... 2005-06-16 19:57:11.3663 Received HTTP code 200: OK 2005-06-16 19:57:11.6844 BackgroundHTTP calling callback with response data 2005-06-16 19:57:11.6848 ==handleHandshakeResponse() 2005-06-16 19:57:11.6850 UPTODATE D1EAEBBEE1B0D32D2979876600A8B42A http://post.audioscrobbler.com:80/protocol_1.1 INTERVAL 1 2005-06-16 19:57:11.6857 ==parseHandshakeResultFromContent() 2005-06-16 19:57:11.6860 2005-06-16 19:57:11.6862 Got MD5 Challenge : D1EAEBBEE1B0D32D2979876600A8B42A 2005-06-16 19:57:11.6866 Got Post URL : http://post.audioscrobbler.com:80/protocol_1.1 2005-06-16 19:57:11.6869 Got INTERVAL : 1 2005-06-16 19:57:11.6872 ==doBackgroundSubmit() 2005-06-16 19:57:11.6889 Requesting POST on URL: "http://post.audioscrobbler.com:80/protocol_1.1" 2005-06-16 19:57:11.6895 Posting data: u=kevindf&s=43e55c6b9f2342e6f4e5dee09d6f3349&a[0]=EVANESCENCE&b[0]=Fallen&t[0]=Bring%20Me%20To%20Life&l[0]=237&i[0]=2005-05-20%2021%3A42%3A13&m[0]=&a[1]=Evanescence&b[1]=Fallen&t[1]=Bring%20 ... 2005-06-16 19:57:11.6967 ==BackgroundHHTP.post 2005-06-16 19:57:11.6980 Using proxy 10.6.1.254:8080 2005-06-16 19:57:11.6987 10.6.1.254 is already resolved 2005-06-16 19:57:11.6991 Connecting to 10.6.1.254:8080 2005-06-16 19:57:11.7033 Connected. Sending request... 2005-06-16 19:57:12.7038 Received HTTP code 200: OK 2005-06-16 19:57:12.7046 BackgroundHTTP calling callback with response data 2005-06-16 19:57:12.7049 ==handleSubmitResponse() 2005-06-16 19:57:12.7051 FAILED Plugin bug: Not all request variables are set : userName = null INTERVAL 1 2005-06-16 19:57:12.7056 AudioScrobbler POST Error: Plugin bug: Not all request variables are set : userName = null 2005-06-16 19:57:12.7060 Setting interval: 1 2005-06-16 19:57:12.7063 Waiting before retry 2005-06-16 19:57:12.7066 Setting interval: 60
Hi kdf, Thanks for that. Okay: the first observation is that not only did we not see the crash, but we didn't see the cause of the crash happen. My fix is supposed to log when it catches the die, and it looks like it didn't see the triggering behaviour from the server. You talked before about having to "hack a way through" your proxy. Can you elaborate on this? If you were connecting directly before, and via a proxy now, then it's likely that the proxy will conceal the bad HTTP flow you were seeing from AS. So can I get you, if possible, to clear out your webproxy setting, reinstate your hack through the proxy (whatever it was - code or config) and try again? I'm hoping to see a line like "HTTP request died with: EOF instead of response status line" in the debug output. If the inclusion of proxy support makes doing this impossible, then grab http://cvs.sourceforge.net/viewcvs.py/*checkout*/slimscrobbler/SlimScrobbler/SlimScrobbleSupport/Scrobbler/BackgroundHTTP.pm?rev=1.8 and replace the version of SlimScrobblerSupport/Scrobbler/BackgroundHTTP.pm - that will give you the fix to the die, but not proxy support. With regards to the null username problem; that is an error from AudioScrobbler rather than the Slim plugin. The strange thing is that the username is clearly included in the POST data. So either the whole submission body is getting lost somewhere en route, or AudioScrobbler is getting confused by the number of tracks in the submission. The latter seems most likely - you say the backlog is huge, just how huge? Thanks Ian
where the code had commented: if we want proxy support the proxy goes here instead of host and port, I hard-coded my proxy and port. Its possible that a blank response was the result of an improper connection. as for the backlog, I wiped it out and started with a single new song and still got the same error. I suspect that the post isnt' getting through the proxy properly. as the setup to have all this happen is on my work computer, it will have to wait until monday. I'll try out the older module then.
I have tried to test, but I am getting error reponses back from the server, database too busy. I am having no crashes, so I guess a failure doesn't cause the blank response: 2005-06-20 10:15:03.4855 BackgroundHTTP calling callback with response data 2005-06-20 10:15:03.4862 ==handleHandshakeResponse() 2005-06-20 10:15:03.4867 FAILED Database too busy - try later. INTERVAL 1 2005-06-20 10:15:03.4879 ==parseHandshakeResultFromContent() 2005-06-20 10:15:03.4885 AudioScrobbler HTTP Error: Couldn't find URL in GET response! 2005-06-20 10:15:03.4890 Handshake failure, waiting before retry 2005-06-20 10:15:03.4895 Setting interval: 960 2005-06-20 10:15:46.0023 RssNews screensaver character limit exceeded. Displaying fewer than 3 items. This is while using the older BackgroundHTTP.pm module and patching for proxy as I had before.
ok, finally got a response with the EOF. hopefully this helps: 2005-06-20 12:07:18.2816 BackgroundHTTP calling callback with response data 2005-06-20 12:07:18.2823 ==handleHandshakeResponse() 2005-06-20 12:07:18.2828 UPTODATE A607BCF7FE7D291E1B72A5B6C95E1EDB http://post.audioscrobbler.com:80/protocol_1.1 INTERVAL 1 2005-06-20 12:07:18.2845 ==parseHandshakeResultFromContent() 2005-06-20 12:07:18.2850 2005-06-20 12:07:18.2856 Got MD5 Challenge : A607BCF7FE7D291E1B72A5B6C95E1EDB 2005-06-20 12:07:18.2861 Got Post URL : http://post.audioscrobbler.com:80/protocol_1.1 2005-06-20 12:07:18.2866 Got INTERVAL : 1 2005-06-20 12:07:18.2872 ==doBackgroundSubmit() 2005-06-20 12:07:18.2905 Requesting POST on URL: "http://post.audioscrobbler.com:80/protocol_1.1" 2005-06-20 12:07:18.2912 Posting data: u=kevindf&s=54a15e9bf75a3aea766b0bf83a3b898d&a[0]=GREEN%20DAY&b[0]=American%20Idiot&t[0]=Holiday&l[0]=233&i[0]=2005-06-17%2017%3A48%3A08&m[0]=&a[1]=GREEN%20DAY&b[1]=American%20Idiot&t[1]=Bou levard%20of%20Broken%20Dreams&l[1]=260&i[1]=2005-06-17%2017%3A51%3A58&m[1]=&a[2]=SARAH%20MCLACHLAN&b[2]=Afterglow&t[2]=Fallen&l[2]=227&i[2]=2005-06-20%2017%3A44%3A23&m[2]=&a[3]=Pink&b[3]=Try %20This&t[3]=Oh%20My%20God%20(Feat%20Peaches)&l[3]=223&i[3]=2005-06-20%2017%3A47%3A43&m[3]=&a[4]=U2&b[4]=How%20To%20Dismantle%20An%20Atomic%20Bomb&t[4]=Crumbs%20from%20Your%20Table&l[4]=303& i[4]=2005-06-20%2017%3A52%3A13&m[4]=&a[5]=Artificial%20Joy%20Club&b[5]=Miscellaneous&t[5]=Sick%20And%20Beautiful&l[5]=262&i[5]=2005-06-20%2017%3A56%3A33&m[5]=&a[6]=Bad%20Religion&b[6]=The%20 Process%20Of%20Belief&t[6]=Sorrow&l[6]=201&i[6]=2005-06-20%2018%3A00%3A34&m[6]=&a[7]=Chess&b[7]=Miscellaneous&t[7]=Pity%20The%20Child&l[7]=330&i[7]=2005-06-20%2018%3A04%3A45&m[7]=&a[8]=Clay% 20Aiken&b[8]=Measure%20Of%20A%20Man&t[8]=Invisible&l[8]=244&i[8]=2005-06-20%2018%3A09%3A35&m[8]=&a[9]=Crosby%2C%20Stills%2C%20Nash%20%26%20Young&b[9]=Miscellaneous&t[9]=Southern%20Cross&l[9] =284&i[9]=2005-06-20%2018%3A13%3A55&m[9]=&a[10]=Crosby%2C%20Stills%20%26%20Nash&b[10]=Miscellaneous&t[10]=Suite%20Judy%20Blue%20Eyes&l[10]=443&i[10]=2005-06-20%2018%3A20%3A05&m[10]=&a[11]=ED WIN%20MCCAIN&b[11]=No%20Album&t[11]=I'll%20Be&l[11]=327&i[11]=2005-06-20%2018%3A26%3A25&m[11]=&a[12]=EVANESCENCE&b[12]=Fallen&t[12]=Bring%20Me%20To%20Life&l[12]=236&i[12]=2005-06-20%2018%3A3 1%3A16&m[12]=&a[13]=EVANESCENCE&b[13]=Fallen&t[13]=Everybody's%20Fool&l[13]=196&i[13]=2005-06-20%2018%3A34%3A46&m[13]=&a[14]=EVANESCENCE&b[14]=Fallen&t[14]=Going%20Under&l[14]=214&i[14]=2005 -06-20%2018%3A38%3A16&m[14]=&a[15]=EVANESCENCE&b[15]=Fallen&t[15]=Haunted&l[15]=196&i[15]=2005-06-20%2018%3A41%3A36&m[15]=&a[16]=EVANESCENCE&b[16]=Fallen&t[16]=Hello&l[16]=220&i[16]=2005-06- 20%2018%3A45%3A06&m[16]=&a[17]=EVANESCENCE&b[17]=Fallen&t[17]=Imaginary&l[17]=257&i[17]=2005-06-20%2018%3A49%3A06&m[17]=&a[18]=EVANESCENCE&b[18]=Fallen&t[18]=Missing&l[18]=255&i[18]=2005-06- 20%2018%3A53%3A26&m[18]=&a[19]=EVANESCENCE&b[19]=Fallen&t[19]=My%20Immortal&l[19]=264&i[19]=2005-06-20%2018%3A57%3A47&m[19]=&a[20]=EVANESCENCE&b[20]=Fallen&t[20]=My%20Last%20Breath&l[20]=247 &i[20]=2005-06-20%2019%3A01%3A57&m[20]=&a[21]=EVANESCENCE&b[21]=Fallen&t[21]=Taking%20Over%20Me&l[21]=230&i[21]=2005-06-20%2019%3A05%3A57&m[21]=& 2005-06-20 12:07:18.2945 ==BackgroundHHTP.post 2005-06-20 12:07:18.3095 Performing background DNS resolution on post.audioscrobbler.com 2005-06-20 12:07:18.3106 ...using nameserver 10.6.1.22 2005-06-20 12:07:18.4540 post.audioscrobbler.com resolves to 62.216.251.200 2005-06-20 12:07:18.4546 Connecting to 62.216.251.200:80 2005-06-20 12:07:18.4707 Connected. Sending request... 2005-06-20 12:07:18.4740 HTTP request died with: EOF instead of response status line at D:\slim\server\CPAN/Net/HTTP/Methods.pm line 300. ...propagated at D:\slim\server\CPAN/Net/HTTP/NB.pm line 32. 2005-06-20 12:07:18.4750 BackgroundHTTP calling callback with failure 2005-06-20 12:07:18.4755 ==handleSubmitResponse() 2005-06-20 12:07:18.4759 No connection made, will not rehandshake 2005-06-20 12:07:18.4796 Waiting before retry 2005-06-20 12:07:18.4803 Setting interval: 60
kdf, thanks for trying this. I've successfully run SlimScrobbler against a different open proxy (and confirmed submissions), so I'm not able to recreate your problem... I also suspect that the POST data is being dropped by the proxy; is there anything you can do to investigate further and/or confirm this? It may be that SlimScrobbler needs to include some additional headers in the HTTP request or something, but I'm not sure what. (To the Slim people: the original problem described by this bug has, I believe, been fixed, and will be released the next time we refresh SlimScrobbler.)
I've been runing this for a week and no crashes, so yes, I think that confirms this bug is fixed. The rest, can be handled through the plugin list.
This bug appears to have been fixed in the latest release! If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look. Make sure to include the version number of the software you are seeing the error with.