May also be affecting 7.3.3.

http://forums.slimdevices.com/showthread.php?p=426306#

I've tested this and it's working fine for me. Make sure you have the plugin enabled _and_ the service is active on the player. If in doubt, disable/enable and try again.

Michael, I have both plugin and service active - as you can see from the log above, the plugin is submitting, or at least purporting too (and I assume it wouldn't do this unless the plugin/service was active) and I've tried enable/disable and clear all settings/cache via the Control Panel.  I even tried revalidating my Last.fm account in Squeezenetwork.  There just seem to be too many people experiencing this problem in 7.4 for it to be a settings issue.

Did you test on XP, I assume so?  I wonder if it could be other plugins?  I have iPlayer and Other Players installed - will try with those disabled.

Will try a complete fresh reinstall of SC later and see if that gives any improvement.

Likewise: I didn't make any changes to things, it just stopped.

an ngrep (cause I like how it prints instead of tcpdump :)

T 76.115.148.254:57923 -> 195.24.233.58:80 [AP]
  POST /protocol_1.2 HTTP/1.1..Connection: close..Cache-Control: no-cache..Accept: */*..Accept-Encoding: deflate, gzip..Accept-Language: en..Host: post2.audioscrobbler.com..User-Agent: iTunes/4.7.1 (Linux; N; Debian; i686-linux; EN; utf8) SqueezeCenter/7.4/26754..Content-Type: application/x-www-form-urlencoded..Icy-Metadata: 1..Content-Length:178....s=2a5f17bb4fac4b16a8cce3e7f3f1bd83&l[0]=394&n[0]=3&r[0]=&a[0]=&b[0]=Mercy%20Now&m[0]=4c95db15-0bb1-4559-8938-e22bbae74969&o[0]=P&i[0]=1243621090&t[0]=Wheel%20Inside%20the%20Wheel                                                                                                                                               
##
T 195.24.233.58:80 -> 76.115.148.254:57923 [AP]
  HTTP/1.1 200 OK..Server: Apache-Coyote/1.1..Pragma: no-cache..Cache-Control: no-cache..Content-Type: text/plain..Date: Fri, 29 May 2009 18:22:15 GMT..Connection: close.
  ...OK.

So that says it -is- submitting it... and lastfm is accepting it.

But how come a[0] is empty?

The LastFM API says that this is the artist and is mandatory.

See my comments elsewhere about Fishbone and other skins seeming to drop the Artist from the display in 7.4.

Is some "currentTrack->artist" type variable different in the sql-lite tree?

Alan: I think this is related to your primary artist changes.  I believe that may be affecting other areas of the UI too.

> But how come a[0] is empty?
>
> The LastFM API says that this is the artist and is mandatory.

You might be up to something: I noticed the artist on the Controller was  
all wrong, while it's ok on the classic display and in the web UI. But my  
Biography plugin is getting a wrong artist, too. I wonder whether the  
scrobbling issue is due to some artist information being wrong issue.

Yep the missing artist is the issue.

This is a consequence of the cause underlying bug 12208

Should be fixed in change 26779.

Created attachment 5299 [details]
Server.log

(In reply to comment #9)
> Should be fixed in change 26779.

I've just upgraded to v26797 and scrobbling still isn't worked for me.  I see the same behaviour I describe above (song appears in Last.fm recently played whilst playing but drops out of the recently played list when the song finishes).  I also have the same log entries appearing in the log well after the song has finished playing:

[09-06-02 10:58:54.0023] Slim::Plugin::AudioScrobbler::Plugin::submitScrobble (834) Scrobbling 1 queued item(s)
[09-06-02 10:58:54.0050] Slim::Plugin::AudioScrobbler::Plugin::submitScrobble (856) Track Heavyweight%20Champion%20of%20the%20World is still playing, not submitting

Log attached

Andy, can you comment on this latest log please? The "a=..." element from the submission element is no longer empty.

The "still playing" messages should only appear if you for example pause the track for a while.

(In reply to comment #12)
> The "still playing" messages should only appear if you for example pause the
> track for a while.

I didn't pause the track at all - just it up to play as a test and left it running.

(In reply to comment #13)
> (In reply to comment #12)
> > The "still playing" messages should only appear if you for example pause the
> > track for a while.

Just tried again with the latest version available by automatic update (Version: 7.4 - 26808 @ Tue Jun 2 06:45:45 PDT 2009). I see the same behaviour with scrobbling.

I've also noticed this in the logs - what is the significance of the "scrobble queue" - could it be that I have a backlog of queued items whis is what is causing the now playing tracks not to committ?  May try deleting the cache again to see if it makes a difference.

09-06-02 17:49:44.7984] Slim::Plugin::AudioScrobbler::Plugin::newsongCallback (448) Submitting scrobble queue before now playing track
[09-06-02 17:49:44.7992] Slim::Plugin::AudioScrobbler::Plugin::submitScrobble (834) Scrobbling 1 queued item(s)
[09-06-02 17:49:44.8035] Slim::Plugin::AudioScrobbler::Plugin::submitScrobble (856) Track Heavyweight%20Champion%20of%20the%20World is still playing, not submitting
[09-06-02 17:49:44.8047] Slim::Plugin::AudioScrobbler::Plugin::newsongCallback (513) New track to scrobble: Heavyweight Champion of the World, will check in 102 seconds
[09-06-02 17:50:44.0102] Slim::Plugin::AudioScrobbler::Plugin::submitScrobble (834) Scrobbling 1 queued item(s)
[09-06-02 17:50:44.0123] Slim::Plugin::AudioScrobbler::Plugin::submitScrobble (856) Track Heavyweight%20Champion%20of%20the%20World is still playing, not submitting

Deleting the cache doesn't help.  Looking at the logs again, the timing doesn't seem quite right.  The song starts playing at 18:18:03 and is 4.04 mins long, so should be scrobbling at 122 seconds.

However, when it reaches 122 seconds (18:20:06) the log appears to show that it is now queueing the track for a further 122 seconds before scrobbling - which I guess is why it thinks it's still playing long after it's finished? 

[09-06-02 18:18:03.5696] Slim::Plugin::AudioScrobbler::Plugin::handshake (289) Handshaking with Last.fm: http://post.audioscrobbler.com/?hs=true&p=1.2&c=ss7&v=sc7.4&u=Siduhe&t=1243963083&a=0e454559cbc3af72323a25180470473b
[09-06-02 18:18:03.5733] Slim::Plugin::AudioScrobbler::Plugin::newsongCallback (513) New track to scrobble: 1 Thing (radio edit), will check in 122 seconds
[09-06-02 18:18:03.7971] Slim::Plugin::AudioScrobbler::Plugin::_handshakeOK (305) Handshake OK, session id: cdb489cfbe8943e7b3722af1edc20972, np URL: http://post.audioscrobbler.com:80/np_1.2, submit URL: http://post2.audioscrobbler.com:80/protocol_1.2
[09-06-02 18:18:03.8121] Slim::Plugin::AudioScrobbler::Plugin::submitNowPlaying (581) Submitting Now Playing track to Last.fm: s=cdb489cfbe8943e7b3722af1edc20972&a=Amerie&t=1%20Thing%20(radio%20edit)&b=1%20Thing&l=244&n=1&m=6537f196-420a-47fa-b1f1-4f5147771891
[09-06-02 18:18:03.8880] Slim::Plugin::AudioScrobbler::Plugin::_submitNowPlayingOK (608) Now Playing track submitted successfully
[09-06-02 18:19:22.6863] Slim::Networking::IO::Select::__ANON__ (113) Error: Select task failed calling Slim::Web::HTTP::processHTTP: Not a HASH reference at C:/PROGRA~1/SQUEEZ~3/server/Slim/Plugin/Extensions/Settings.pm line 139.
[09-06-02 18:20:05.5833] Slim::Plugin::AudioScrobbler::Plugin::checkScrobble (743) 1 Thing (radio edit) - Not yet reached 122 playback seconds, waiting 0.400999999999996 more seconds
[09-06-02 18:20:05.9936] Slim::Plugin::AudioScrobbler::Plugin::checkScrobble (743) 1 Thing (radio edit) - Not yet reached 122 playback seconds, waiting 0.400999999999996 more seconds
[09-06-02 18:20:06.3891] Slim::Plugin::AudioScrobbler::Plugin::checkScrobble (758) 1 Thing (radio edit) - Queueing track for scrobbling in 122 seconds
[09-06-02 18:22:18.3928] Slim::Plugin::AudioScrobbler::Plugin::submitScrobble (834) Scrobbling 1 queued item(s)
[09-06-02 18:22:18.4044] Slim::Plugin::AudioScrobbler::Plugin::submitScrobble (856) Track 1%20Thing%20(radio%20edit) is still playing, not submitting

Created attachment 5301 [details]
Server.log

At the risk of talking to myself here, after playing some more tracks last night and upgrading to Version: 7.4 - 26820, I think the problem I am having with scrobbling tracks is more limited.  I've attached a new server.log covering last night and today.

It only affects a) playlists with only one track in and b) the last track in every playlist.  If I queue up a playlist with six tracks in, the first five will scrobble ok.  However, before any of the six scrobbles, SC will submit the last track from the previous playlist. If you look at the attached log, the last track I played last night (Amerie - 1 Thing) didn't scrobble at the time (6:19pm local on 2 June) but did scrobble just now when I started playing a new playlist.  This appears to be because of the restart of the timing issue I mentioned in my last post.

I've just played another playlist with two songs in (Adele - Daydreamer and Sugababes - About You Know).  Adele has scrobbled ok (after Amerie did) but About you Know hasn't.

If you look at my last.fm page (http://www.last.fm/user/Siduhe) you can see the Amerie track has only scrobbled this morning, despite being played last night).

I can live with this as it gets caught up eventually, but curious if this is only affecting me or others see the same - I think new users will find it a bit strange that single tracks don't get scrobbled immediately if this is now the default behaviour.  Anyway, last post on this topic - promise!

Ok, I understand what is happening. This is a different bug - does not scrobble last track in playlist. This is because (since 7.3), the "current" track when one gets to the end of a playlist is the last track whereas, before 7.3, it would wrap around to the first track. Please open a new bug. You can assign it to me.

Done as bug #12240.

https://bugs-archive.lyrion.org/show_bug.cgi?id=12240

I think this problem may still subsist for Napster tracks which are not scrobbling as they used to - is this the same issue or a different one (with apologies to Michael, to whom I said I wouldn't raise any new bug issues for at least a few days...):


[09-06-04 21:14:00.1669] Slim::Plugin::AudioScrobbler::Plugin::submitNowPlaying (563) Protocol Handler didn't return an artist and title for napster://track:16677332.wma, ignoring
[09-06-04 21:14:00.1687] Slim::Plugin::AudioScrobbler::Plugin::newsongCallback (490) Protocol Handler didn't return an artist and title for napster://track:16677332.wma, ignoring
[09-06-04 21:14:11.6363] Slim::Plugin::Napster::ProtocolHandler::_gotBulkMetadata (479) Caching metadata for 20 tracks

It looks like the scrobbling code tried to submit now playing info before the track metadata was received.  When you play a Napster or Rhapsody album or playlist, the metadata is fetched in the background.  Not sure of the best way to fix that, but it deserves a separate bug.

(In reply to comment #20)
> It looks like the scrobbling code tried to submit now playing info before the
> track metadata was received.  When you play a Napster or Rhapsody album or
> playlist, the metadata is fetched in the background.  Not sure of the best way
> to fix that, but it deserves a separate bug.

Ok thanks Andy, (sorry Michael).  Should it be assigned to anyone in particular?

Assign it to me.

This bug has been marked as fixed in the 7.4.0 release version of SqueezeBox Server!
    * SqueezeCenter: 28672
    * Squeezebox 2 and 3: 130
    * Transporter: 80
    * Receiver: 65
    * Boom: 50
    * Controller: 7790
    * Radio: 7790  

Please see the Release Notes for all the details: http://wiki.slimdevices.com/index.php/Release_Notes

If you haven't already, please download and install the new version from http://www.logitechsqueezebox.com/support/download-squeezebox-server.html

If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.