iScrobbler 1.0.0 statistics window and queue problems
Since yesterday I've been experiencing some odd behavior using iScrobbler 1.0.0 with iTunes 4.7.1(30). I first noticed this when my recently played tracks weren't being added to my profile page. Knowing that the audioscrobbler servers get a complete hammering I wasn't too concerned until I noticed that it was intermittent and that when it did get updated songs were missing.
I've tailed the iScrobbler Log at TRACE level (would hiding the password be possible/or worth it?) and everything looks in order to the point where there's a submission and only one track gets sent. Rewind through the log and there's a whole sequence of songs that have been happily added then queued. The reflection of the log in the statistics window is also out as the que number stays at 0, although the light grey 'now playing' text is right.
Re: iScrobbler 1.0.0 statistics window and queue problems
Quoth fruitcake:
Since yesterday I've been experiencing some odd behavior using iScrobbler 1.0.0 with iTunes 4.7.1(30). I first noticed this when my recently played tracks weren't being added to my profile page. Knowing that the audioscrobbler servers get a complete hammering I wasn't too concerned until I noticed that it was intermittent and that when it did get updated songs were missing.
Well, subs are about three days behind now. So anything after Feb 1 is still in the server's queue waiting to be processed. That will account for your "missing" songs. Subs processing is back on now, but it will take a day or more to catch up. There are 4.5 million songs waiting for processing.
I've tailed the iScrobbler Log at TRACE level (would hiding the password be possible/or worth it?)
Not really. If you're worried about it, just use the Clean Log menu item and the log file will be erased.
and everything looks in order to the point where there's a submission and only one track gets sent. Rewind through the log and there's a whole sequence of songs that have been happily added then queued. The reflection of the log in the statistics window is also out as the que number stays at 0, although the light grey 'now playing' text is right.
Any ideas?
The queue # is local to iScrobbler, it does not reflect the separate server queue. So, as long as the server accepted what we sent, we clear our local queue whether the server put the data in its own queue or not (in fact there is no way for the client to know either way).
This is all normal. As the server is severly backlogged right now, you will see a huge delay between the time a song is submitted (and accepted) and when it is actually processed and put into your profile.
I fear the server backlog isn't the issue. If i disconnect from the net, and allow the songs to queue in the plugin, it only seems to add some to the queue, from what I can see in the 'statistics' window.
Another indicator - if I am online, and in the statistics page, open 'Show Submission Details', it shows a track submitted a good 20 minutes ago, but the number alongside 'Tracks Queued for Submission' remains at zero - so some tracks seem to have gone missing...?
A similar phenomenon has been affecting my iScrobbler clients, but in a much more mysterious manner.
I listen to my music library from three different machines; at two different locations; using two different methods. Two thirds of the clients are experiencing the exact same submission issue. Without going into too much detail, here is a summary:
Machine #01: iTunes 4.7.1(30), iScrobbler 1.0.0, MacOS 10.3.7, 802.3 (10b-T); accesses the music library via a DAAP share from the server through an ssh tunnel from work.
No problems, whatsoever. All tracks played are eventually submitted successfully, albeit slowly given recent server backlogs).
Machine #02: iTunes 4.7.1(30), iScrobbler 1.0.0, MacOS 10.3.7, 804.11b; access to the music library via a DAAP share from the server.
Only a small fraction of the tracks to which I have listened are submitted. Average of around five to six percent.
Machine #03: iTunes 4.7.1(30), iScrobbler 1.0.0, MacOS 10.3.7, 802.3 (100b-T); access to the master music library "locally" (via an NFS share to the directory upon the server in which the entire library is housed.
Same result as the second client, with the exception that there are a few more successes per attempt. Average of around fifteen to eighteen percent.
Other facts:
All machines are behind a firewall of some sort, but both implementations allow unhampered outbound HTTP traffic. Machine #01 has a web proxy for inbound; machines #02 and #03 are allowed no inbound requests (port forwarding only to the internal server).
As of yesterday evening, the log verbosity was escalated to "TRACE" on machines #02 and #03 for diagnostic purposes. The information recorded was identical to that which Simon reports. Several tracks are logged and reported to be queued for submission (though it does not appear that an attempt is made to actually initiate the upload). However, the statistics window does not reflect these queued tracks. Every once in a while the scrobbler client *will* initiate a connection, but only the last track is sent. Any others in the queue are ignored.
Quoth JPfineUK:
I fear the server backlog isn't the issue. If i disconnect from the net, and allow the songs to queue in the plugin, it only seems to add some to the queue, from what I can see in the 'statistics' window.
Are any of those songs < 30 seconds or missing Artist/Title info? If so, iScrobbler won't even queue them for submission. Those are the protocol rules.
Otherwise, every song played is queued for submission.
Another indicator - if I am online, and in the statistics page, open 'Show Submission Details', it shows a track submitted a good 20 minutes ago, but the number alongside 'Tracks Queued for Submission' remains at zero - so some tracks seem to have gone missing...?
You mean Last Track Sumitted is showing a song played 20 minutes ago and the queue is empty? Does Tracks Submitted increase?
[Feb 04, 2005 15:07:34 +0000]-[VERB] Added 'The Great Beyond, In Time: The Best of R.E.M. 1988-2003, R.E.M.'
[Feb 04, 2005 15:07:54 +0000]-[VERB] Added 'How Can We Hang on to a Dream?, American Trilogy, The Delgados'
[Feb 04, 2005 15:07:57 +0000]-[VERB] Added 'The Glow Pt. 2, Glow Pt. 2, The Microphones'
[Feb 04, 2005 15:07:58 +0000]-[VERB] Added 'Yes, Out Of Our Heads On Skelp, Aereogramme'
[Feb 04, 2005 15:09:02 +0000]-[VERB] Queuing song 'Yes, Out Of Our Heads On Skelp, Aereogramme' for submission
[Feb 04, 2005 15:09:03 +0000]-[INFO] 1 song(s) submitted...
[Feb 04, 2005 15:09:44 +0000]-[VERB] Submission result: OK
INTERVAL 1
As of yesterday evening, the log verbosity was escalated to "TRACE" on machines #02 and #03 for diagnostic purposes. The information recorded was identical to that which Simon reports. Several tracks are logged and reported to be queued for submission (though it does not appear that an attempt is made to actually initiate the upload). However, the statistics window does not reflect these queued tracks. Every once in a while the scrobbler client *will* initiate a connection, but only the last track is sent. Any others in the queue are ignored.
1) Queued but delayed sub: How are your machines connected, ethernet, modem, USB ethernet? I ask because 1.0.0 includes connection monitoring, and if OS X thinks your connection is not active, then you will not see any sub attempts until the connection becomes active. If you have VERB or TRACE on, you will see the following in the log when a sub is attempted on an inactive connection:
Network is not available, submissions are being queued.
2) The Last Track Submitted will always be that, the last track submitted. Even if you have a queue of 50 songs and all the songs are submitted, only the last one will be shown in that field. When a sub attempt is made (eg for 50 songs) you will see in the log:
[INFO] 50 song(s) submitted...
So it sounds to me like everything is working, and you just need to wait for the server backlog to catch up.
You can post your log (please not the whole thing -- just relevant portions) and I'll take a look at it, but I don't think there's a problem here (not with iScrobbler anyway).
[Feb 04, 2005 15:07:34 +0000]-[VERB] Added 'The Great Beyond, In Time: The Best of R.E.M. 1988-2003, R.E.M.'
[Feb 04, 2005 15:07:54 +0000]-[VERB] Added 'How Can We Hang on to a Dream?, American Trilogy, The Delgados'
[Feb 04, 2005 15:07:57 +0000]-[VERB] Added 'The Glow Pt. 2, Glow Pt. 2, The Microphones'
[Feb 04, 2005 15:07:58 +0000]-[VERB] Added 'Yes, Out Of Our Heads On Skelp, Aereogramme'
[Feb 04, 2005 15:09:02 +0000]-[VERB] Queuing song 'Yes, Out Of Our Heads On Skelp, Aereogramme' for submission
[Feb 04, 2005 15:09:03 +0000]-[INFO] 1 song(s) submitted...
[Feb 04, 2005 15:09:44 +0000]-[VERB] Submission result: OK
INTERVAL 1
I have iTunes 4.7.1 (30) and 10.3.7
Uhh, you are not playing the songs all the way through. A song is not submitted unless it has played for half the length of the track or 4 mins (whichever comes first). These are also the protocol rules. Looks to me like you may be trying to SPAM the server and that's why these rules are in effect.
Aah yes sorry that was a bad section of log to take... I have been listening to songs all the way through, honest!
[Feb 04, 2005 16:33:57 +0000]-[VERB] Added 'Y Teimlad, Mwng, Super Furry Animals'
[Feb 04, 2005 16:36:21 +0000]-[VERB] Queuing song 'Y Teimlad, Mwng, Super Furry Animals' for submission
[Feb 04, 2005 16:38:32 +0000]-[VERB] Added 'Cheating The Game, Moving Up Country, James Yorkston And The Athletes'
[Feb 04, 2005 16:40:29 +0000]-[VERB] Queuing song 'Cheating The Game, Moving Up Country, James Yorkston And The Athletes' for submission
[Feb 04, 2005 16:42:14 +0000]-[VERB] Added 'Holding A Drink, Like Others Need Oxygen Comes With A Smile Vol 8, Mendoza Line'
[Feb 04, 2005 16:44:04 +0000]-[VERB] Queuing song 'Holding A Drink, Like Others Need Oxygen Comes With A Smile Vol 8, Mendoza Line' for submission
[Feb 04, 2005 16:45:41 +0000]-[VERB] Added 'Last Night I Dreamt That Somebody Loved Me, Last Night I Dreamt That Somebody Loved Me, Low'
[Feb 04, 2005 16:47:42 +0000]-[VERB] Queuing song 'Last Night I Dreamt That Somebody Loved Me, Last Night I Dreamt That Somebody Loved Me, Low' for submission
[Feb 04, 2005 16:48:15 +0000]-[VERB] Queuing song 'Last Night I Dreamt That Somebody Loved Me, Last Night I Dreamt That Somebody Loved Me, Low' for submission
[Feb 04, 2005 16:48:15 +0000]-[INFO] 1 song(s) submitted...
[Feb 04, 2005 16:48:19 +0000]-[VERB] Submission result: OK
INTERVAL 1
Quoth Damaged:
1) Queued but delayed sub: How are your machines connected, ethernet, modem, USB ethernet? I ask because 1.0.0 includes connection monitoring, and if OS X thinks your connection is not active, then you will not see any sub attempts until the connection becomes active. If you have VERB or TRACE on, you will see the following in the log when a sub is attempted on an inactive connection:
Network is not available, submissions are being queued.
Perhaps, but that is not the situation here. The connection types are listed in the summaries of the individual machines. One of the affected machines is a wireless (802.11b; sorry, my typo by stating 804.11b initially), while the other is Ethernet (802.3).
I think you are misunderstanding what the three of us are describing. It is not that the tracks are actually being queued for submission. Rather the log indicates acknowledgement and queuing, but the statistics window does not recognize this, nor does it increment the queue ticker or submit the tracks.
Here is a step-by-step breakdown...
a) a song is queued for play within iTunes
b) the track information is broadcast by iTunes
c) iScrobbler receives this information and is logging it correctly
d) the client (iScrobbler) then indicates that the track has been queued in its cache for submission. Whether or not the network is available, there is often no attempt to actually contact the Scrobbler servers as a result of this event.
e) though the log indicates that the track has been queued for submission, the "Tracks Queued for Submission" does not always increment - in fact, it rarely increments.
f) every once in a while (very erratic) a track will be queued, be logged as being queued, and increment the queue ticker. This track will trigger a connection attempt by iScrobber, but *ONLY* this last track will be submitted - whether one, ten or fifty have previously been logged as having been queued!
The only common factor I can appreciate, with respect to the affected machines, is that they are at my home with communication occurring between my domestic LAN and the Scrobbler servers through my ISP (broadband, cable). The machine which experiences no issue is at work and communicating via a T3 connection.
I will be happy to submit an excerpted log section, but that will have to wait until I get home this evening. Meanwhile, I think that John has provided some insight - though only at the VERBose level.
JPPineUK (and others): OK, that log does look wrong. That Queuing msg should actually be "Attempting to queue" and obviously the attempt failed for some reason. My guess is that iTunes is giving us the wrong play position information and according to that the track is not actually ready for submission. DoctorT has seen this exact iTunes bug with some of his CD's and it's very easy to see from the iTunes track dump that we do at TRACE level. This bug never occurs with files though, but it may occur over iTunes Sharing. JPPineUK are you using a CD or iTunes Sharing?
Given the above, could you all please download 1.0.1 test 1, set your log level to TRACE, and then post short sections of the log that show the problem (like JPPineUK did). I've added some extra TRACE logging to the queue manager to see what is happening. And in this version, the Queuing msg means just that, the song has actually been queued -- sorry about the confusion with that in 1.0.0.
Here are the other 1.0.1 changes:
- The Top Artists list now includes the total time played for each artist.
- Copy/Drag and Drop now work for the Top Lists tables. The data is formatted as TSV and can easily be pasted into a spreadsheet.
- The Tracks Submitted stat is now only updated after a submission attempt completes.
- Fixed bug that caused a song already in the submission queue and then played again to only be submitted once.
Thanks guys, I just wasn't getting what you were saying. So I guess the moral is always post log excerpts so my dense mind can see exactly what is going on.
P.S. FWIW, I have tested Sharing access from iTunes to iTunes and w/o fail the tracks are submitted. This is over a wired GigE connection though.
I was wondering if their problem was at all related to the one I had (am still wondering, for that matter). I wonder if iTunes has problems with timings when there is a time delay getting data off a cd or a network. Of, course, it could be that I haven't the foggiest idea what I'm talking about.
Anyway, just grabbed 1.0.1 test 1 and will be using it.
Thanks Damaged for sorting this out so quickly... and giving me an opportunity not to do my essay ;)
I'm afraid this isn't a small excerpt exactly, but it's only three songs! 'The Boy With a Thorn in his Side' was the last song to submit correctly...
[Feb 04, 2005 21:52:16 +0000]-[TRACE] iTunes notification received: Playing
[Feb 04, 2005 21:52:16 +0000]-[TRACE] Song components from iTunes result: (
1032,
1,
"The Boy With The Thorn In His Side",
197,
0,
"The Smiths",
"The Queen Is Dead",
"File Track",
"",
0
)
[Feb 04, 2005 21:52:16 +0000]-[VERB] Added 'The Boy With The Thorn In His Side, The Queen Is Dead, The Smiths'
[Feb 04, 2005 21:52:16 +0000]-[TRACE] Firing mainTimer: in 103.00 seconds for track 'The Boy With The Thorn In His Side, The Queen Is Dead, The Smiths'.
[Feb 04, 2005 21:52:16 +0000]-[TRACE] -[iScrobblerController iTunesPlayerInfoHandler:]:139 -- iTunesLastPlayedTime == 2005-02-04 21:52:16 +0000
[Feb 04, 2005 21:54:00 +0000]-[TRACE] Song components from iTunes result: (
1032,
1,
"The Boy With The Thorn In His Side",
197,
101,
"The Smiths",
"The Queen Is Dead",
"File Track",
"",
0
)
[Feb 04, 2005 21:54:00 +0000]-[VERB] Queuing song 'The Boy With The Thorn In His Side, The Queen Is Dead, The Smiths' for submission
[Feb 04, 2005 21:54:00 +0000]-[VERB] Need to handshake.
[Feb 04, 2005 21:54:00 +0000]-[VERB] Handshaking... http://post.audioscrobbler.com/?hs=true&u=JPfineUK&p=1.1&v=1.0.1&c=osx
[Feb 04, 2005 21:54:30 +0000]-[TRACE] Song components from iTunes result: (
1032,
1,
"The Boy With The Thorn In His Side",
197,
130,
"The Smiths",
"The Queen Is Dead",
"File Track",
"",
0
)
[Feb 04, 2005 21:54:30 +0000]-[TRACE] Song '<SongData: 0x1e1470> The Boy With The Thorn In His Side, The Queen Is Dead, The Smiths (id: 0)' is already queued for submission. Ignoring.
[Feb 04, 2005 21:55:01 +0000]-[VERB] Handshake result: FAILED
Connection failed - timed out
[Feb 04, 2005 21:55:24 +0000]-[TRACE] iTunes notification received: Playing
[Feb 04, 2005 21:55:24 +0000]-[TRACE] Song components from iTunes result: (
1033,
1,
"Know-How",
238,
0,
"Kings Of Convenience",
"Riot On An Empty Street",
"File Track",
"",
0
)
[Feb 04, 2005 21:55:24 +0000]-[VERB] Added 'Know-How, Riot On An Empty Street, Kings Of Convenience'
[Feb 04, 2005 21:55:24 +0000]-[TRACE] Firing mainTimer: in 123.00 seconds for track 'Know-How, Riot On An Empty Street, Kings Of Convenience'.
[Feb 04, 2005 21:55:24 +0000]-[TRACE] -[iScrobblerController iTunesPlayerInfoHandler:]:139 -- iTunesLastPlayedTime == 2005-02-04 21:55:24 +0000
[Feb 04, 2005 21:56:01 +0000]-[VERB] Re-trying handshake after delay...
[Feb 04, 2005 21:56:01 +0000]-[VERB] Handshaking... http://post.audioscrobbler.com/?hs=true&u=JPfineUK&p=1.1&v=1.0.1&c=osx
[Feb 04, 2005 21:56:38 +0000]-[VERB] Handshake result: UPTODATE
9B970B1228A8B21C93896F5C6FEED4B2 http://post.audioscrobbler.com:80/protocol_1.1
INTERVAL 1
[Feb 04, 2005 21:56:38 +0000]-[INFO] 1 song(s) submitted...
[Feb 04, 2005 21:57:06 +0000]-[TRACE] Tracks in queue after submission: 1
[Feb 04, 2005 21:57:06 +0000]-[VERB] Submission result: OK
INTERVAL 1
[Feb 04, 2005 21:57:06 +0000]-[TRACE] Queue cleaned, track count: 0
[Feb 04, 2005 21:57:27 +0000]-[TRACE] Song components from iTunes result: (
1033,
1,
"Know-How",
238,
113,
"Kings Of Convenience",
"Riot On An Empty Street",
"File Track",
"",
0
)
[Feb 04, 2005 21:57:27 +0000]-[TRACE] Song 'Know-How, Riot On An Empty Street, Kings Of Convenience [238]' failed submission rules. Not queuing.
[Feb 04, 2005 21:59:19 +0000]-[TRACE] iTunes notification received: Playing
[Feb 04, 2005 21:59:19 +0000]-[TRACE] Song components from iTunes result: (
1034,
1,
"Jed's Other Poem (Beautiful Ground)",
205,
0,
Grandaddy,
"The Sophtware Slump",
"File Track",
"",
0
)
[Feb 04, 2005 21:59:19 +0000]-[VERB] Added 'Jed's Other Poem (Beautiful Ground), The Sophtware Slump, Grandaddy'
[Feb 04, 2005 21:59:19 +0000]-[TRACE] Firing mainTimer: in 107.00 seconds for track 'Jed's Other Poem (Beautiful Ground), The Sophtware Slump, Grandaddy'.
[Feb 04, 2005 21:59:19 +0000]-[TRACE] -[iScrobblerController iTunesPlayerInfoHandler:]:139 -- iTunesLastPlayedTime == 2005-02-04 21:59:19 +0000
[Feb 04, 2005 22:01:06 +0000]-[TRACE] Song components from iTunes result: (
1034,
1,
"Jed's Other Poem (Beautiful Ground)",
205,
94,
Grandaddy,
"The Sophtware Slump",
"File Track",
"",
0
)
[Feb 04, 2005 22:01:06 +0000]-[TRACE] Song 'Jed's Other Poem (Beautiful Ground), The Sophtware Slump, Grandaddy [205]' failed submission rules. Not queuing.
Yep, just as I expected, you're hitting the iTunes bug that DoctorT found with his CD's. Are you playing a CD or Shared iTunes music from another computer?
I'll do a play-by-play for the TRACE:
[Feb 04, 2005 21:55:24 +0000]-[TRACE] iTunes notification received: Playing
[Feb 04, 2005 21:55:24 +0000]-[TRACE] Song components from iTunes result: (
1033,
1,
"Know-How",
238,
0,
"Kings Of Convenience",
"Riot On An Empty Street",
"File Track",
"",
0
)
We get a notification from iTunes that a new song is playing at 9:55:24 PM local time. The song is 238 seconds long.
[Feb 04, 2005 21:55:24 +0000]-[TRACE] Firing mainTimer: in 123.00 seconds for track 'Know-How, Riot On An Empty Street, Kings Of Convenience'.
Since you are using iTunes 4.7, there is no need for us to poll iTunes so we just setup our internal timer to fire in 123 seconds which is 1/2 the song length (119) + 4 seconds of padding just to "make sure" the track is 1/2 done.
[Feb 04, 2005 21:57:27 +0000]-[TRACE] Song components from iTunes result: (
1033,
1,
"Know-How",
238,
113,
"Kings Of Convenience",
"Riot On An Empty Street",
"File Track",
"",
0
)
And at 9:57:27 PM local time the timer is fired and iTunes queried for the info of the currently playing song (which is still Know-How). As you can see, 123 seconds have elapsed (9:55:24 + 123 seconds = 9:57:27) in the real world. But, look at the dump we get from iTunes: the 3rd field is the track name, the fourth the track duration, and the fifth the current postion of the song as iTunes sees it -- 113 seconds of play time elapsed. And, 113 is less than 119 (1/2 the duration of the song).
So, either you seeked the song (backwards), or iTunes is sending us bad data. Assuming you didn't seek (which is also against the protocol rules) then this is an iTunes bug.
[Feb 04, 2005 21:57:27 +0000]-[TRACE] Song 'Know-How, Riot On An Empty Street, Kings Of Convenience [238]' failed submission rules. Not queuing.
And since 1/2 the song has not elapsed (according to iTunes) the song fails the submission rules.
The same bug happens for your next song, and I'd be willing to bet that the same bug is affecting velociped.
DoctorT: I'd be inclined to agree with you on the data loading issue, especially since iTunes probably streams CD tracks since the files are so big, and of course network songs are streamed.
Now, with a network stream it would be possible to have to re-buffer some of the song if a network error occured, and that could cause the elapsed play time to not match with the elapsed real-world time, but I don't see how that could affect a CD, unless the CD was damaged.
So, to get to the point, I don't have a good workaround for this problem. I don't really want to go back to polling iTunes -- it would solve the problem, but it uses tons of CPU. I could also bump the pad time added to the fire time, but how do I know how much to add, since it seems the missing time interval is random? If anyone has suggesstions on how to work around this bug, post 'em.
Hmm... Well here are a couple of things it could be...
- I'm playing from an iPod through iTunes.
- I'm using AirTunes to play the music through my hifi, and there is a buffer to connect to the external speakers.
Either one of these?
I suspect it is the former, but I don't really want to transfer everything from my iPod to my HD - it would fill up my measly iBook HD unfortunately... Any workaround?
update: yup, that's done the trick. how embarrassing *blushes*... When you have it on crossfade, iTunes chooses the next track before it actually starts playing it, hence the time anomalies.
Quoth JPfineUK: update: yup, that's done the trick. how embarrassing *blushes*... When you have it on crossfade, iTunes chooses the next track before it actually starts playing it, hence the time anomalies.
That makes sense since the two tracks would be playing at the same time. Nice catch!
Well, I did end up thinking of a hack to deal with this problem. And since there is still a possibility of failing because of network errors -- having it is a good thing.
1.0.1 test 2 will now detect if a queue failed, and then retry the queue again in half of the remaining play time left in the track. JPfineUK, could you turn Crossfade back on and try again with test 2. You should see something like the following in the log:
"Track 'Know-How, Riot On An Empty Street, Kings Of Convenience'
failed submission rules. Possilble iTunes time shift. Trying again in 62 seconds."
I do not use nor have I ever used crossfade. I will play a couple of the cds I know had problems using 1.0.1 test 2 to see what happens. Unfortunately, if the problem does not appear does not necessarily mean the problem has gone away or been fixed. As I had remarked, all the tracks have at some point been submitted.
I do sometimes hear the cd-drive ramp up, but I haven't paid any attention to see if there is any correlation with skipped tracks, but there could be a buffer problem. I will try to pay attention to what noises my powerbook makes and what happens with iTunes and iScrobbler.
Quoth Damaged:
This bug never occurs with files though, but it may occur over iTunes Sharing. JPPineUK are you using a CD or iTunes Sharing?
It would be advisable to refrain from absolutes, Brian. One of the affected machines in my case is accessing the track files directly. Admittedly, over a 100Base-T NFS share, but directly, nonetheless.
I missed the opportunity to try 1.0.1 test 1, but snagged a copy of 1.0.1 test 2. So far, so good.
Taking a gander at the log, I see exactly what you describe. iScrobbler detects the track broadcast from iTunes and fires the half-life timer. iTunes is queried at T<sub>50</sub> at which point iScrobbler finds that it has failed to complete 50% of track length, disqualifies the track for submission, but goes back to sleep for another half-life. Upon reawakening, iScrobbler queries iTunes to find that the track has conformed to the protocol parameters and queues the track for submission. Great! ...if it holds.
Sorry to be a cynic, but I am dubious of the diagnosis that it is either a share lag and/or a CD buffer lag. The theory of the crossfade also lacks complete credibility. Like Tom, one of my affected systems has crossfade turned off completely (As an aside, the machine which sports a flawless submission record has been configured with crossfade buffers ranging from two to six seconds and not experienced the phenomenon.) My attention has been drawn to another possibility, though.
John remarked that he is playing from an iPod to an Airport Express (AE). Both of my affected systems regularly stream to my sound system via an AE. So, I have to wonder if that device had some influence.
I have only upgraded one of the Scrobbler clients for testing. Before I leave the issue completely, I am going to play around with the other affected system in order to try to discover which of these four hypotheses (or any combination thereof) may be contributing the most.
Fifteen tracks out of 15 tracks from the first cd successfully submitted. I have 2 more cds that I remember had problems and I will play them as well. There have been other cds with problems, and if I remember which ones they are I will try them.
I remember hearing the drive ramp up - in listening to the noises during this last cd, it seems there is some seeking at the beginning of many of the tracks.
Quoth velociped: Quoth Damaged:
This bug never occurs with files though, but it may occur over iTunes Sharing. JPPineUK are you using a CD or iTunes Sharing?
It would be advisable to refrain from absolutes, Brian. One of the affected machines in my case is accessing the track files directly. Admittedly, over a 100Base-T NFS share, but directly, nonetheless.
You're taking things too literally. Do I have to qualify every single one of my statements with "in my experience". In my experience with 1.0 and iTunes 4.7 (no track polling) I've never seen a problem with MP3/AAC files played from a local hard disk -- that's close to 3000 tracks played.
Also, if you are going over NFS, that's not really direct as you're still subject to network outages (probably very rare). Also, I believe I said that the error would occur from network stream re-buffering. And I guessed that CD tracks are "streamed" (although it's more like they are read in at fixed sized chunks) because they are so big. iTunes can likely read most AAC/MP3 files in one shot and then play directly from memory -- no lag to speak of. But for large compressed files it probably reads them in chunks too. Who knows, it may even mmap large files, and then you are talking about "streaming" done at the block size level (for NFS that's usually 8-32KiB).
...
Upon reawakening, iScrobbler queries iTunes to find that the track has conformed to the protocol parameters and queues the track for submission. Great! ...if it holds.
Sorry to be a cynic, but I am dubious of the diagnosis that it is either a share lag and/or a CD buffer lag. The theory of the crossfade also lacks complete credibility.
Well it's just that, a theory -- as I don't have access to the iTunes source, that's all it will ever be, but for network streams it is the most likely scenario. CD"s are probably not streamed, but they are likely not buffered in memory as full songs either, so a damaged CD could cause the same type of problem.
As for crossfade, JPfineUK proposed that, and as soon as he turned it off, things started working. He didn't say he changed anything else in his config -- so I went off of the info he gave.
John remarked that he is playing from an iPod to an Airport Express (AE). Both of my affected systems regularly stream to my sound system via an AE. So, I have to wonder if that device had some influence.
-HIM-
Well, an Airprot Express is a fairly slow network, and depending on the signal it can drop out all toghether and cause a stream rebuffer -- which leads us back to my original theory.
Quoth DamagedJPfineUK, could you turn Crossfade back on and try again with test 2. You should see something like the following in the log:
"Track 'Know-How, Riot On An Empty Street, Kings Of Convenience'
failed submission rules. Possilble iTunes time shift. Trying again in 62 seconds."
Yup, with crossfade back on, the new version submits perfectly... There are still one or two double submissions, but I suspect that is a different issue?
iScrobbler 1.0.0 statistics window and queue problems