Not Scrobbling

[dannymichel]

Please take a look at my log.

2015-01-08 14:40:02,803 [952] [main <module>] [DEBUG] config : mediaserver_log_location -> /Users/danny/Library/Logs/Plex Media Server.log
2015-01-08 14:40:02,804 [952] [main <module>] [DEBUG] config : session -> /Users/danny/.config/plex-lastfm-scrobbler/session_key
2015-01-08 14:40:02,804 [952] [main <module>] [DEBUG] config : mediaserver_url -> http://localhost:32400
2015-01-08 14:40:02,804 [952] [main <module>] [DEBUG] config : config file location -> /Users/danny/.config/plex-lastfm-scrobbler/plex_scrobble.conf
2015-01-08 14:40:02,804 [952] [main <module>] [DEBUG] config : log_file -> /tmp/plex_scrobble.log
2015-01-08 14:40:02,804 [952] [main <module>] [DEBUG] config : cache_location -> /tmp/plex_scrobble.cache
2015-01-08 14:40:02,804 [952] [main <module>] [INFO] Prompting to authenticate to Last.fm.
2015-01-08 14:56:18,542 [1029] [main <module>] [DEBUG] config : mediaserver_log_location -> /Users/danny/Library/Logs/Plex Media Server.log
2015-01-08 14:56:18,542 [1029] [main <module>] [DEBUG] config : session -> /Users/danny/.config/plex-lastfm-scrobbler/session_key
2015-01-08 14:56:18,542 [1029] [main <module>] [DEBUG] config : mediaserver_url -> http://localhost:32400
2015-01-08 14:56:18,542 [1029] [main <module>] [DEBUG] config : config file location -> /Users/danny/.config/plex-lastfm-scrobbler/plex_scrobble.conf
2015-01-08 14:56:18,542 [1029] [main <module>] [DEBUG] config : log_file -> /tmp/plex_scrobble.log
2015-01-08 14:56:18,542 [1029] [main <module>] [DEBUG] config : cache_location -> /tmp/plex_scrobble.cache
2015-01-08 14:56:18,542 [1029] [main <module>] [INFO] Prompting to authenticate to Last.fm.
2015-01-09 13:34:05,986 [14066] [main <module>] [DEBUG] config : mediaserver_log_location -> /Users/danny/Library/Logs/Plex Media Server.log
2015-01-09 13:34:05,987 [14066] [main <module>] [DEBUG] config : session -> /Users/danny/.config/plex-lastfm-scrobbler/session_key
2015-01-09 13:34:05,987 [14066] [main <module>] [DEBUG] config : mediaserver_url -> http://localhost:32400
2015-01-09 13:34:05,987 [14066] [main <module>] [DEBUG] config : config file location -> /Users/danny/.config/plex-lastfm-scrobbler/plex_scrobble.conf
2015-01-09 13:34:05,987 [14066] [main <module>] [DEBUG] config : log_file -> /tmp/plex_scrobble.log
2015-01-09 13:34:05,987 [14066] [main <module>] [DEBUG] config : cache_location -> /tmp/plex_scrobble.cache
2015-01-09 13:34:05,987 [14066] [main <module>] [INFO] Prompting to authenticate to Last.fm.
2015-01-09 13:48:25,822 [14299] [main <module>] [DEBUG] config : mediaserver_log_location -> /Users/danny/Library/Logs/Plex Media Server.log
2015-01-09 13:48:25,822 [14299] [main <module>] [DEBUG] config : session -> /Users/danny/.config/plex-lastfm-scrobbler/session_key
2015-01-09 13:48:25,822 [14299] [main <module>] [DEBUG] config : mediaserver_url -> http://localhost:32400
2015-01-09 13:48:25,822 [14299] [main <module>] [DEBUG] config : config file location -> /Users/danny/.config/plex-lastfm-scrobbler/plex_scrobble.conf
2015-01-09 13:48:25,822 [14299] [main <module>] [DEBUG] config : log_file -> /tmp/plex_scrobble.log
2015-01-09 13:48:25,822 [14299] [main <module>] [DEBUG] config : cache_location -> /tmp/plex_scrobble.cache
2015-01-09 13:48:25,823 [14299] [main <module>] [INFO] Prompting to authenticate to Last.fm.
2015-01-09 13:48:47,690 [14299] [plex_scrobble.lastfm last_fm_auth] [INFO] Last.FM authorization successful.
2015-01-09 13:48:47,691 [14299] [main <module>] [WARNING] Exiting application.
2015-01-09 13:49:17,782 [14318] [main <module>] [DEBUG] config : mediaserver_log_location -> /Users/danny/Library/Logs/Plex Media Server.log
2015-01-09 13:49:17,782 [14318] [main <module>] [DEBUG] config : session -> /Users/danny/.config/plex-lastfm-scrobbler/session_key
2015-01-09 13:49:17,782 [14318] [main <module>] [DEBUG] config : mediaserver_url -> http://localhost:32400
2015-01-09 13:49:17,782 [14318] [main <module>] [DEBUG] config : config file location -> /Users/danny/.config/plex-lastfm-scrobbler/plex_scrobble.conf
2015-01-09 13:49:17,782 [14318] [main <module>] [DEBUG] config : log_file -> /tmp/plex_scrobble.log
2015-01-09 13:49:17,782 [14318] [main <module>] [DEBUG] config : cache_location -> /tmp/plex_scrobble.cache
2015-01-09 13:49:17,782 [14318] [main <module>] [DEBUG] using last.fm session key=/Users/danny/.config/plex-lastfm-scrobbler/session_key , st_mtime=Fri Jan  9 13:48:47 2015
2015-01-09 13:49:17,782 [14318] [main cache_retry] [INFO] starting cache_retry thread.
2015-01-09 13:49:17,796 [14318] [main main] [INFO] starting log monitor thread.
2015-01-09 13:51:01,047 [14318] [plex_scrobble.plex_monitor parse_line] [INFO] Found played song and extracted library id '54413' from plex log 
2015-01-09 13:51:01,047 [14318] [plex_scrobble.plex_monitor fetch_metadata] [INFO] Fetching library metadata from http://localhost:32400/library/metadata/54413
2015-01-09 13:51:01,063 [14318] [plex_scrobble.lastfm scrobble] [INFO] submitting The Marshall Tucker Band - Ramblin' (Marshall Tucker Band) to last.fm.
2015-01-09 13:51:11,071 [14318] [plex_scrobble.plex_monitor parse_line] [INFO] Found played song and extracted library id '54413' from plex log 
2015-01-09 13:51:11,072 [14318] [plex_scrobble.plex_monitor monitor_log] [WARNING] Dupe detection : 54413, not submitting

[jesseward]

@dannymichel thanks for the report. Based on the following

2015-01-09 13:51:01,047 [14318] [plex_scrobble.plex_monitor parse_line] [INFO] Found played song and extracted library id '54413' from plex log 
2015-01-09 13:51:01,047 [14318] [plex_scrobble.plex_monitor fetch_metadata] [INFO] Fetching library metadata from http://localhost:32400/library/metadata/54413
2015-01-09 13:51:01,063 [14318] [plex_scrobble.lastfm scrobble] [INFO] submitting The Marshall Tucker Band - Ramblin' (Marshall Tucker Band) to last.fm.

it looks as though it scrobbled a single track. Did it stop submitting after this entry? If so can you pass along your /Users/danny/Library/Logs/Plex Media Server.log that matches up with this time as well? If it is a large file , feel free to paste it in http://pastebin.com

[dannymichel]

I lost the log that corresponds with that time.
If I ever do get this to work, would you mind telling me to to set this command up to run during startup on my Mac?

[unclev]

Mine is likely not @dannymichel's case, but it also causes "Not Scrobbling" issue.
Plex Home Theater sometimes does not write "Library item (\d+) '.*' got played by account" line.
Grep "Down The Line" from "Plex Media Server.log" where "Down The Line" was not submitted:

victor@unclev:/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Logs$ grep "Down The Line" "Plex Media Server.log.bak"
Jan 20, 2015 12:33:03 [0x7f7372ffd700] DEBUG - Content-Length of /media/data/Plex/Music/Foreign/Lewis, Jerry Lee/Rock & Roll Forever (unofficial)/09 Jerry Lee Lewis - Down The Line.mp3 is 5384497.
Jan 20, 2015 12:33:03 [0x7f7372ffd700] DEBUG - Content-Length of /media/data/Plex/Music/Foreign/Lewis, Jerry Lee/Rock & Roll Forever (unofficial)/09 Jerry Lee Lewis - Down The Line.mp3 is 5384497.
Jan 20, 2015 12:33:04 [0x7f73937fe700] DEBUG - Content-Length of /media/data/Plex/Music/Foreign/Lewis, Jerry Lee/Rock & Roll Forever (unofficial)/09 Jerry Lee Lewis - Down The Line.mp3 is 5384497.
Jan 20, 2015 12:33:39 [0x7f7372ffd700] DEBUG - Play progress on 14044 'Down The Line' - got played 30033 ms by account 1!
Jan 20, 2015 12:34:09 [0x7f7370ff9700] DEBUG - Play progress on 14044 'Down The Line' - got played 60283 ms by account 1!
Jan 20, 2015 12:34:39 [0x7f7370ff9700] DEBUG - Play progress on 14044 'Down The Line' - got played 90483 ms by account 1!
Jan 20, 2015 12:35:10 [0x7f7370ff9700] DEBUG - Play progress on 14044 'Down The Line' - got played 120763 ms by account 1!

"Breathless" was submitted:

victor@unclev:/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Logs$ grep "Breathless" "Plex Media Server.log.bak"
Jan 20, 2015 12:35:17 [0x7f7370ff9700] DEBUG - Content-Length of /media/data/Plex/Music/Foreign/Lewis, Jerry Lee/Rock & Roll Forever (unofficial)/10 Jerry Lee Lewis - Breathless.mp3 is 6509852.
Jan 20, 2015 12:35:17 [0x7f7372ffd700] DEBUG - Content-Length of /media/data/Plex/Music/Foreign/Lewis, Jerry Lee/Rock & Roll Forever (unofficial)/10 Jerry Lee Lewis - Breathless.mp3 is 6509852.
Jan 20, 2015 12:35:18 [0x7f7370ff9700] DEBUG - Content-Length of /media/data/Plex/Music/Foreign/Lewis, Jerry Lee/Rock & Roll Forever (unofficial)/10 Jerry Lee Lewis - Breathless.mp3 is 6509852.
Jan 20, 2015 12:35:53 [0x7f7372ffd700] DEBUG - Play progress on 14045 'Breathless' - got played 29765 ms by account 1!
Jan 20, 2015 12:36:23 [0x7f7372ffd700] DEBUG - Play progress on 14045 'Breathless' - got played 59945 ms by account 1!
Jan 20, 2015 12:36:53 [0x7f7372ffd700] DEBUG - Play progress on 14045 'Breathless' - got played 90065 ms by account 1!
Jan 20, 2015 12:37:23 [0x7f73937fe700] DEBUG - Play progress on 14045 'Breathless' - got played 120335 ms by account 1!
Jan 20, 2015 12:37:53 [0x7f73937fe700] DEBUG - Library item 14045 'Breathless' got played by account 1!

The corresponding piece of the plex_scrobble.log:

victor@unclev:/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Logs$ grep "2015-01-20 12:" plex_scrobble.log
2015-01-20 12:07:04,014 [1893] [plex_scrobble.plex_monitor monitor_log] [DEBUG] Possible log file rotation, resetting file handle (st_mtime=Tue Jan 20 12:06:04 2015)
2015-01-20 12:08:36,030 [1893] [plex_scrobble.plex_monitor monitor_log] [DEBUG] Possible log file rotation, resetting file handle (st_mtime=Tue Jan 20 12:07:36 2015)
2015-01-20 12:15:59,007 [1893] [plex_scrobble.plex_monitor monitor_log] [DEBUG] Possible log file rotation, resetting file handle (st_mtime=Tue Jan 20 12:14:59 2015)
2015-01-20 12:17:14,022 [1893] [plex_scrobble.plex_monitor monitor_log] [DEBUG] Possible log file rotation, resetting file handle (st_mtime=Tue Jan 20 12:16:14 2015)
2015-01-20 12:27:25,014 [1893] [plex_scrobble.plex_monitor monitor_log] [DEBUG] Possible log file rotation, resetting file handle (st_mtime=Tue Jan 20 12:26:25 2015)
2015-01-20 12:37:54,198 [1893] [plex_scrobble.plex_monitor parse_line] [INFO] Found played song and extracted library id '14045' from plex log
2015-01-20 12:37:54,205 [1893] [plex_scrobble.plex_monitor fetch_metadata] [INFO] Fetching library metadata from http://unclev.ru:32400/library/metadata/14045
2015-01-20 12:37:54,310 [1893] [plex_scrobble.lastfm scrobble] [INFO] submitting Jerry Lee Lewis - Breathless (Rock and Roll Rebel) to last.fm.
2015-01-20 12:52:03,335 [1893] [main cache_retry] [INFO] starting cache_retry thread.

I tried to add

, re.compile('.*\sDEBUG\s-\sPlay\sprogress\son\s(\d+)\s\'.*\'\s-\sgot\splayed\s(\d+)\sms\sby\saccount.*')

into the REGEX list in plex_monitor.py, but this didn't help.

Plex Server version: 0.9.8.10 from the PPA on 64-bit Ubuntu 12.04 in my home LAN,
Plex Home Theater version: 1.2.3.378 on 64-bit Windows 8.1 in my office LAN.

[lionpants]

Similar problem here. The scrobbling works for a few hours then stops scrobbling properly. If I reboot the computer that the Plex server is running on and start the script again, it works properly for a while before running into the same issue.

2015-01-23 11:23:17,003 [3440] [plex_scrobble.plex_monitor monitor_log] [DEBUG] Possible log file rotation, resetting file handle (st_mtime=Fri Jan 23 11:22:17 2015)

2015-01-23 12:08:28,085 [3440] [main cache_retry] [INFO] starting cache_retry thread.

"starting cache_retry thread" is where it always gets stuck, it then just spams that log entry until I reboot. Maybe a recent Plex update to how it handles the logging broke this?

It should be noted that I am also running the Trakt.tv scrobbling channel on the server, but I have had this problem before using the Trakt.tv scrobbler.