I just finished the second album, this one has 58 tracks, many of them short and every-time I have played some tracks (not counting the ones less than 30 seconds) have been skipped, and this play was no exception. Three tracks were skipped on the first play-through. When I went back and played those tracks individually, they were all submitted.
Song 1:
[Feb 04, 2005 20:44:21 -0500]-[VERB] Queuing track 'Wakes In The Morning, Warner Collection : Vol. 1-Her Bright Smile Haunts, Edith Perrin' for submission [Feb 04, 2005 20:44:21 -0500]-[WARN] Already connected to server, delaying submission... [Feb 04, 2005 20:44:22 -0500]-[INFO] Connection error -- tracks in queue: 2 [Feb 04, 2005 20:44:33 -0500]-[TRACE] iTunes notification received: Playing [Feb 04, 2005 20:44:33 -0500]-[TRACE] Song components from iTunes result: ( 12, 1, "Where Did You Get That Hat?", 39, 33, "Edith Perrin", "Warner Collection : Vol. 1-Her Bright Smile Haunts", "File Track", "", 0 ) [Feb 04, 2005 20:44:33 -0500]-[VERB] Added 'Where Did You Get That Hat?, Warner Collection : Vol. 1-Her Bright Smile Haunts, Edith Perrin' [Feb 04, 2005 20:44:33 -0500]-[TRACE] Firing mainTimer: in 24.00 seconds for track 'Where Did You Get That Hat?, Warner Collection : Vol. 1-Her Bright Smile Haunts, Edith Perrin'. [Feb 04, 2005 20:44:33 -0500]-[TRACE] -[iScrobblerController iTunesPlayerInfoHandler:]:139 -- iTunesLastPlayedTime == 2005-02-04 20:44:33 -0500 [Feb 04, 2005 20:45:12 -0500]-[TRACE] iTunes notification received: Playing [Feb 04, 2005 20:45:12 -0500]-[TRACE] Song components from iTunes result: ( 13, 1, "Mail Day Blues",
Song 2
Something came up and I paused this song about 60% of the way through and again about 95% of the way through. When the song was finished I started play on the same song and it went through the second time. Log is for play 1.
[Feb 04, 2005 21:28:41 -0500]-[TRACE] Track '<SongData: 0x1e4ffb0> Tommy, Warner Collection : Vol. 1-Her Bright Smile Haunts, Martha Midgett (id: 116)' is already queued for submission. Ignoring. [Feb 04, 2005 21:28:57 -0500]-[TRACE] iTunes notification received: Playing [Feb 04, 2005 21:28:57 -0500]-[TRACE] Song components from iTunes result: ( 36, 1, "Hold My Hand Lord Jesus", 125, 63, "Sue Thomas", "Warner Collection : Vol. 1-Her Bright Smile Haunts", "File Track", "", 0 ) [Feb 04, 2005 21:28:57 -0500]-[VERB] Added 'Hold My Hand Lord Jesus, Warner Collection : Vol. 1-Her Bright Smile Haunts, Sue Thomas' [Feb 04, 2005 21:28:57 -0500]-[TRACE] Firing mainTimer: in 4.00 seconds for track 'Hold My Hand Lord Jesus, Warner Collection : Vol. 1-Her Bright Smile Haunts, Sue Thomas'. [Feb 04, 2005 21:28:57 -0500]-[TRACE] -[iScrobblerController iTunesPlayerInfoHandler:]:139 -- iTunesLastPlayedTime == 2005-02-04 21:28:57 -0500 [Feb 04, 2005 21:29:01 -0500]-[TRACE] Song components from iTunes result: ( 36, 1, "Hold My Hand Lord Jesus",
Song 3
[Feb 05, 2005 09:28:35 -0500]-[VERB] Queuing track 'Poor Ellen Smith, Warner Collection : Vol. 1-Her Bright Smile Haunts, Homer Cornett' for submission [Feb 05, 2005 09:28:35 -0500]-[INFO] 5 song(s) submitted... [Feb 05, 2005 09:29:17 -0500]-[TRACE] iTunes notification received: Playing [Feb 05, 2005 09:29:18 -0500]-[TRACE] Song components from iTunes result: ( 54, 1, "Johnson Boys", 55, 94, "Frank Proffitt", "Warner Collection : Vol. 1-Her Bright Smile Haunts", "File Track", "", 0 ) [Feb 05, 2005 09:29:18 -0500]-[VERB] Added 'Johnson Boys, Warner Collection : Vol. 1-Her Bright Smile Haunts, Frank Proffitt' [Feb 05, 2005 09:29:18 -0500]-[TRACE] Firing mainTimer: in 32.00 seconds for track 'Johnson Boys, Warner Collection : Vol. 1-Her Bright Smile Haunts, Frank Proffitt'. [Feb 05, 2005 09:29:18 -0500]-[TRACE] -[iScrobblerController iTunesPlayerInfoHandler:]:139 -- iTunesLastPlayedTime == 2005-02-05 09:29:18 -0500 [Feb 05, 2005 09:30:13 -0500]-[TRACE] iTunes notification received: Playing [Feb 05, 2005 09:30:13 -0500]-[TRACE] Song components from iTunes result: ( 55, 1, "Little Maggie",
Now on to the third cd I know has skipped tracks multiple times in the past. This next cd has a couple tracks that have been skipped fairly consistently (although not 100%), so I will be interested in seeing what happens.
Tom
EDIT: 3rd cd submitted all tracks with no problems. I'm playing a 4th pulled more-or-less at random from my shelf.
[Feb 04, 2005 20:44:33 -0500]-[TRACE] Firing mainTimer: in 24.00 seconds for track 'Where Did You Get That Hat?, Warner Collection : Vol. 1-Her Bright Smile Haunts, Edith Perrin'. [Feb 04, 2005 20:44:33 -0500]-[TRACE] -[iScrobblerController iTunesPlayerInfoHandler:]:139 -- iTunesLastPlayedTime == 2005-02-04 20:44:33 -0500 [Feb 04, 2005 20:45:12 -0500]-[TRACE] iTunes notification received: Playing [Feb 04, 2005 20:45:12 -0500]-[TRACE] Song components from iTunes result: ( 13, 1, "Mail Day Blues",
The timer never fired here. Since that should be impossible, the only thing I can surmise is that it did fire, but you were doing something in iTunes that caused the AppleScript we run to block and we missed that song. I just added the following to the ChangeLog in 1.0.1:
- If you are burning a CD in iTunes, or editing a song's information, then iTunes cannot process Apple Events. Since iScrobbler communicates with iTunes with Apple Events, this can cause iScrobbler to miss songs that should be submitted.
Especially on a song this short (39 seconds).
Song 2 and Song 3 looks to be the same problem, the mainTimer didn't fire.
I wonder -- if you have a slow or damaged CD, this can cause iTunes to block too and not process AppleScripts. This may be happening it you weren't doing one of the above activities (network stream re-buffering will cause the same problem). Our AppleScript may be timing out and if that's the case, the song will not be setup to fire again.
I'll take a look at our error handling for script errors and see if I can work something out similar to the Queue error handling.
OK, you posted your response while I posted my edit, which was that the 3rd cd played with everything submitted.
While the cd with 3 skipped tracks was playing, I was basically reading forum posts and some news sites, as I recall. Also, as I had mentioned before, I bought this cd new and it has only been played a half-dozen times and has been handled by its edges and stored in its case, so it is unlikely (but not definitely) undamaged.
I had long ago discovered that tunes won't submit if you have Get Info open, even for a different track. I was backing up my playlist and burning a lot of cds last week while playing tunes on my computer. I don't recall any tunes that were not submitted.
I've uploaded 1.0.1 test 3. If there is a script execution error in the mainTimer, you'll see a log (with the error info) and the mainTimer will fire again in 2.5 seconds (since we can't rely on the play position). *Sigh* another hack.
I've played another 3 cds or so using tests 2 & 3 with no skipped tracks. The track skipping was not all that common, when I think about the number of cds I play. The problem does appear to like certain cds, such as the first three I tested today and last night. I will try to remember to keep track of which cds have problems and see if I can find anything in common amongst them that might explain it.
Here is another skipped song from a cd. All the songs around it were placed in the local cache and were successfully submitted when contact with the servers was established.
[Feb 06, 2005 15:32:54 -0500]-[VERB] Queuing track 'Willoughby's Farm, Best Of British Folk - Original Recordings - Original Artists, Ralph McTell' for submission [Feb 06, 2005 15:32:54 -0500]-[INFO] 6 song(s) submitted... [Feb 06, 2005 15:33:54 -0500]-[TRACE] iTunes notification received: Playing [Feb 06, 2005 15:33:54 -0500]-[TRACE] Song components from iTunes result: ( 14, 1, "Noah And The Rabbit", 169, 127, "John Renbourn & Bert Jansch", "Best Of British Folk - Original Recordings - Original Artists", "File Track", "", 0 ) [Feb 06, 2005 15:33:54 -0500]-[VERB] Added 'Noah And The Rabbit, Best Of British Folk - Original Recordings - Original Artists, John Renbourn & Bert Jansch' [Feb 06, 2005 15:33:54 -0500]-[WARN] Invalid submit interval '-38.00' for track 'Noah And The Rabbit, Best Of British Folk - Original Recordings - Original Artists, John Renbourn & Bert Jansch'. Track will not be submitted. Duration: 169, Position: 127. [Feb 06, 2005 15:33:54 -0500]-[TRACE] -[iScrobblerController iTunesPlayerInfoHandler:]:139 -- iTunesLastPlayedTime == 2005-02-06 15:33:54 -0500 [Feb 06, 2005 15:34:17 -0500]-[TRACE] Tracks in queue after submission: 6 [Feb 06, 2005 15:34:17 -0500]-[VERB] Submission result: OK INTERVAL 1 [Feb 06, 2005 15:34:17 -0500]-[TRACE] Queue cleaned, track count: 0 [Feb 06, 2005 15:36:42 -0500]-[TRACE] iTunes notification received: Playing [Feb 06, 2005 15:36:42 -0500]-[TRACE] Song components from iTunes result: ( 15, 1, "Candy Man",
Quoth DoctorT: [Feb 06, 2005 15:33:54 -0500]-[WARN] Invalid submit interval '-38.00' for track 'Noah And The Rabbit, Best Of British Folk - Original Recordings - Original Artists, John Renbourn & Bert Jansch'. Track will not be submitted. Duration: 169, Position: 127.
Negative submit intervals are not allowed. So the question is, why is iTunes notifying us of a brand new play (correct?) that is 127 seconds into the song?
I just played the cd from track one through to the end. I didn't notice this one track was not submitted until I looked at my Recent Tracks. It was submitted successfully when I played it again later. All I was doing while playing the cd was reading posts and surfing the web.
On another front, several of the tracks from this cd appeared in my list twice because the cache did not clear and, even though Russ says that the spam protocol is fixed, they were entered into my profile with doubled play counts.
I just played the cd from track one through to the end. I didn't notice this one track was not submitted until I looked at my Recent Tracks. It was submitted successfully when I played it again later. All I was doing while playing the cd was reading posts and surfing the web.
There are some real problems with iTunes and the data it sends while playing CD's. Anway, what was the duration of the track played just before the missed one? I added some code to deal with iTunes setting the postion of a new track to the duration of the previous one, but it seems that this is not the case in this instance.
On another front, several of the tracks from this cd appeared in my list twice because the cache did not clear and, even though Russ says that the spam protocol is fixed, they were entered into my profile with doubled play counts.
Yes, they said it was fixed on Friday, and I had quite a few dupes yesterday. No dupes today, but I haven't been able to submit for an hour now, and I didn't play too many songs this morning. I think something is still broken.
No problems so far 3/4 of the way through the cd I have on now.
I have been having submissions happens in batches most of the day. Not all of the time is the cache cleared, meaning duplicate submissions (no spam notices today, however) which are added into the play count according to my Profile Editor.
Quoth DoctorT: The duration of the song before was 126.
Ack! Fuckin' iTunes! 1 second off the reported postion of the new track. What a piece of shit!
Well, I guess I can change the code from checking equality to >= duration-1 and <= duration +1. But that may screw up something else (because we get play notifications when the track meta-data is changed too). So I'm not sure if this should be done.
Quoth Damaged: Yes, they said it was fixed on Friday, and I had quite a few dupes yesterday. No dupes today, but I haven't been able to submit for an hour now, and I didn't play too many songs this morning. I think something is still broken.
Well, scratch no dupes today. Just got this 20 minutes ago:
1 Joe Satriani - The Bells Of Lal (Part One) 16:07:42 CST, February 6 2005 2 Joe Satriani - The Bells Of Lal (Part One) 16:07:42 CST, February 6 2005 3 Rosanne Cash - September When It Comes (feat. Johnny Cash) 16:04:01 CST, February 6 2005 4 John Mellencamp - Cherry Bomb 15:59:12 CST, February 6 2005
Not content I'd been testing things out and by the time I'd returned armed with more evidence you'd already tracked down the problem to crossfade and airtunes. Thanks to Brain for sorting this out so quickly. For me 1.0.1 has got things back on track, good luck with doctorT's issue.
I am in agreement with Simon. It is not simply an issue of crossfade or of Airport Express. Rather it appears to be the combination the combination of the two. Turning crossfading off altogether eliminated the problem, in my testing. Likewise, playing the tracks locally within iTunes, but not streaming to the Airport Express, also se4ms to have resolved the issue. Even without testing, this would seem to have been verified by the posts of John, Simon and myself as further discourse on the issue has revealed this to be the uniting factor with the three of us and the anomaly we have experienced.
Many thanks to Brian for the excellent work and the willingness to work with us to diagnose the issue and arrive at a fix — hack though it is. I am in complete agreement with him as well, with respect to iTunes. None of these problems appear to be the fault of iScrobbler; instead being the result of crappy coding at Apple. It would appear that they rushed the "Airtunes" compatible version out without complete testing...or they simply do not care that it munges the track lengths and such.
Though it does not appear to be related, I am interested to see what, if any, fix evolves from the problem Tom has been experiencing. It seems less straight forward in its cause. Nevertheless, is likely just as frustrating.
Thank you again, Brian, for your clever workaround and willingness to indulge our frustrations. :-)
I thought things were going good. I've listened to 7 cds today with no problems. Then, in the middle of the 8th a skipped track:
[Feb 11, 2005 17:54:54 -0500]-[TRACE] Queue cleaned, track count: 0 [Feb 11, 2005 17:56:40 -0500]-[TRACE] iTunes notification received: Playing [Feb 11, 2005 17:56:40 -0500]-[TRACE] Song components from iTunes result: ( 7, 1, "Mo rU00f9n geal U00f2g (My Fair Young Love)", 246, 222, "Anne Lorne Gillies", "O Mo DhU00f9thaich (Oh my land)", "File Track", "", 0 ) [Feb 11, 2005 17:56:40 -0500]-[VERB] Added 'Mo rùn geal òg (My Fair Young Love), O Mo Dhùthaich (Oh my land), Anne Lorne Gillies' [Feb 11, 2005 17:56:40 -0500]-[WARN] Invalid submit interval '-95.00' for track 'Mo rùn geal òg (My Fair Young Love), O Mo Dhùthaich (Oh my land), Anne Lorne Gillies'. Track will not be submitted. Duration: 246, Position: 222. [Feb 11, 2005 17:56:40 -0500]-[TRACE] -[iScrobblerController iTunesPlayerInfoHandler:]:141 -- iTunesLastPlayedTime == 2005-02-11 17:56:40 -0500 [Feb 11, 2005 18:00:46 -0500]-[TRACE] iTunes notification received: Playing [Feb 11, 2005 18:00:46 -0500]-[TRACE] Song components from iTunes result: ( 8, 1, "Soraidh leis a'bhreacan U00f9r (Farewell To The Lovely Tartan)",
EDIT: The drive seems to be doing more seeking (at least, I hear more noises/churning), than with many cds. This might lead back to the idea that there is a negative interaction between iTunes and the drive, as in iTunes not getting data when it expects it.