Bug 1634 - SlimScrobbler causes Slimserver crash while playing
: SlimScrobbler causes Slimserver crash while playing
Status: CLOSED FIXED
Product: Logitech Media Server
Classification: Unclassified
Component: Audio
: 6.1.0
: PC Windows XP
: P2 normal (vote)
: Future
Assigned To: KDF
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2005-06-06 00:24 UTC by James Craig
Modified: 2008-12-15 13:06 UTC (History)
2 users (show)

See Also:
Category: ---


Attachments
patch for test (2.04 KB, patch)
2005-06-08 09:20 UTC, KDF
Details | Diff
log from test (27.78 KB, text/plain)
2005-06-08 09:21 UTC, KDF
Details

Note You need to log in before you can comment on or make changes to this bug.
Description James Craig 2005-06-06 00:24:16 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.
Comment 1 KDF 2005-06-06 14:25:03 UTC
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?
Comment 2 James Craig 2005-06-07 01:27:00 UTC
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.
Comment 3 James Craig 2005-06-07 01:39:34 UTC
is there a bug number for the http problem you refer to - I think I am still
hitting it - cannot find with search...
Comment 4 KDF 2005-06-07 06:49:49 UTC
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'.
Comment 5 KDF 2005-06-07 15:20:17 UTC
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
Comment 6 Blackketter Dean 2005-06-07 16:58:50 UTC
Has this been reported to Stewart, the SlimScrobbler author?
Comment 7 KDF 2005-06-07 19:27:25 UTC
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).
Comment 8 KDF 2005-06-07 20:38:38 UTC
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.
Comment 9 Ian Parkinson 2005-06-08 02:47:35 UTC
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?
Comment 10 KDF 2005-06-08 09:12:28 UTC
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
Comment 11 KDF 2005-06-08 09:20:23 UTC
Created attachment 539 [details]
patch for test
Comment 12 KDF 2005-06-08 09:21:30 UTC
Created attachment 540 [details]
log from test

win2k, slimserver 6.1, slimscrobbler 0.30.  
The last symbol reference is a mystery to me.
Comment 13 KDF 2005-06-10 14:03:44 UTC
retitling for later reference.
Comment 14 Blackketter Dean 2005-06-13 22:18:30 UTC
Pushing this out.  Will revisit if there's an issue in SlimServer to be fixed for 6.1.
Comment 15 KDF 2005-06-14 12:16:33 UTC
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.  
Comment 16 Ian Parkinson 2005-06-15 03:00:00 UTC
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
Comment 17 KDF 2005-06-15 14:57:25 UTC
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.
Comment 18 Ian Parkinson 2005-06-16 13:43:20 UTC
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
Comment 19 KDF 2005-06-16 20:01:39 UTC
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
Comment 20 Ian Parkinson 2005-06-19 14:04:01 UTC
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
Comment 21 KDF 2005-06-19 14:11:22 UTC
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.
Comment 22 KDF 2005-06-20 11:20:47 UTC
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.
Comment 23 KDF 2005-06-20 12:10:40 UTC
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
Comment 24 Ian Parkinson 2005-06-28 14:40:03 UTC
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.)
Comment 25 KDF 2005-06-28 14:51:16 UTC
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.
Comment 26 James Richardson 2008-12-15 13:06:41 UTC
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.