[BugFix] Last Fm Scrobbler corrupted entries

I couldn't seem to reproduce the issue here:
https://forums.rockbox.org/index.php/topic,54165.msg252081.html#msg252081

but I figure its probably a threading issue

so we now have a mutex on the cache

and to top it all off each cached entry has a crc and length that are
checked before writing the entry to the file otherwise it is prepended
with # FAILED - so hopefully scrobbler 'parsers?' don't barf on the log

Other changes:
there is now a MRU table for tracks this should help prevent duplicates
it is configurable..

the cache buffer now no longer uses fixed chunks allowing more tracks
to be written between flushes

Change-Id: Iaab7e3f6a76abfc61130f3233379a51c9a6d12e5

1 files changed, 420 insertions, 124 deletions

diff --git a/apps/plugins/lastfm_scrobbler.c b/apps/plugins/lastfm_scrobbler.c
index c835533b1f..1530ff7ae7 100644
--- a/apps/plugins/lastfm_scrobbler.c
+++ b/apps/plugins/lastfm_scrobbler.c
@@ -21,8 +21,52 @@
  *
  ****************************************************************************/
 /* Scrobbler Plugin
-Audioscrobbler spec at:
+Audioscrobbler spec at: (use wayback machine)
 http://www.audioscrobbler.net/wiki/Portable_Player_Logging
+* EXCERPT:
+* The first lines of .scrobbler.log should be header lines, indicated by the leading '#' character:
+
+#AUDIOSCROBBLER/1.1
+#TZ/[UNKNOWN|UTC]
+#CLIENT/<IDENTIFICATION STRING>
+
+Where 1.1 is the version for this file format
+
+    If the device knows what timezone it is in,
+        it must convert all logged times to UTC (aka GMT+0)
+        eg: #TZ/UTC
+    If the device knows the time, but not the timezone
+        eg: #TZ/UNKNOWN
+
+<IDENTIFICATION STRING> should be replaced by the name/model of the hardware device 
+ and the revision of the software producing the log file.
+
+After the header lines, simply append one line of text for every song
+ that is played or skipped.
+
+The following fields comprise each line, and are tab (\t)
+ separated (strip any tab characters from the data):
+
+    - artist name
+    - album name (optional)
+    - track name
+    - track position on album (optional)
+    - song duration in seconds
+    - rating (L if listened at least 50% or S if skipped)
+    - unix timestamp when song started playing
+    - MusicBrainz Track ID (optional)
+lines should be terminated with \n
+Example
+(listened to enter sandman, skipped cowboys, listened to the pusher) :
+ #AUDIOSCROBBLER/1.0
+ #TZ/UTC
+ #CLIENT/Rockbox h3xx 1.1 
+ Metallica        Metallica        Enter Sandman        1        365        L        1143374412        62c2e20a?-559e-422f-a44c-9afa7882f0c4?
+ Portishead        Roseland NYC Live        Cowboys        2        312        S        1143374777        db45ed76-f5bf-430f-a19f-fbe3cd1c77d3
+ Steppenwolf        Live        The Pusher        12        350        L        1143374779        58ddd581-0fcc-45ed-9352-25255bf80bfb?
+    If the data for optional fields is not available to you, leave the field blank (\t\t).
+    All strings should be written as UTF-8, although the file does not use a BOM.
+    All fields except those marked (optional) above are required.
 */
 
 #include "plugin.h"
@@ -41,18 +85,28 @@ http://www.audioscrobbler.net/wiki/Portable_Player_Logging
 /****************** constants ******************/
 #define EV_EXIT        MAKE_SYS_EVENT(SYS_EVENT_CLS_PRIVATE, 0xFF)
 #define EV_FLUSHCACHE  MAKE_SYS_EVENT(SYS_EVENT_CLS_PRIVATE, 0xFE)
+#define EV_USER_ERROR  MAKE_SYS_EVENT(SYS_EVENT_CLS_PRIVATE, 0xFD)
 #define EV_STARTUP     MAKE_SYS_EVENT(SYS_EVENT_CLS_PRIVATE, 0x01)
 #define EV_TRACKCHANGE MAKE_SYS_EVENT(SYS_EVENT_CLS_PRIVATE, 0x02)
 #define EV_TRACKFINISH MAKE_SYS_EVENT(SYS_EVENT_CLS_PRIVATE, 0x03)
 
-#define SCROBBLER_VERSION "1.1"
+#define ERR_NONE (0)
+#define ERR_WRITING_FILE (-1)
+#define ERR_ENTRY_LENGTH (-2)
+#define ERR_WRITING_DATA (-3)
 
 /* increment this on any code change that effects output */
+#define SCROBBLER_VERSION "1.1"
+
 #define SCROBBLER_REVISION " $Revision$"
 
-#define SCROBBLER_MAX_CACHE 32
+#define SCROBBLER_BAD_ENTRY "# FAILED - "
+
 /* longest entry I've had is 323, add a safety margin */
-#define SCROBBLER_CACHE_LEN 512
+#define SCROBBLER_CACHE_LEN (512)
+#define SCROBBLER_MAX_CACHE (32 * SCROBBLER_CACHE_LEN)
+
+#define SCROBBLER_MAX_TRACK_MRU (32) /* list of hashes to detect repeats */
 
 #define ITEM_HDR "#ARTIST #ALBUM #TITLE #TRACKNUM #LENGTH #RATING #TIMESTAMP #MUSICBRAINZ_TRACKID\n"
 
@@ -67,7 +121,7 @@ static time_t timestamp;
 #define record_timestamp()  ((void)(timestamp = rb->mktime(rb->get_time())))
 #else /* !CONFIG_RTC */
 #define HDR_STR_TIMELESS    " Timeless"
-#define BASE_FILENAME       ".scrobbler-timeless.log"
+#define BASE_FILENAME       HOME_DIR "/.scrobbler-timeless.log"
 #define get_timestamp()     (0l)
 #define record_timestamp()  ({})
 #endif /* CONFIG_RTC */
@@ -76,9 +130,8 @@ static time_t timestamp;
 
 /****************** prototypes ******************/
 enum plugin_status plugin_start(const void* parameter); /* entry */
-
+void play_tone(unsigned int frequency, unsigned int duration);
 /****************** globals ******************/
-unsigned char **language_strings; /* for use with str() macro; must be init */
 /* communication to the worker thread */
 static struct
 {
@@ -89,18 +142,29 @@ static struct
     long stack[THREAD_STACK_SIZE / sizeof(long)];
 } gThread;
 
-static struct
+struct cache_entry
 {
+    size_t   len;
+    uint32_t crc;
+    char     buf[ ];
+};
+
+static struct scrobbler_cache
+{
+    int    entries;
     char  *buf;
-    int    pos;
+    size_t pos;
     size_t size;
     bool   pending;
     bool   force_flush;
+    struct mutex mtx;
 } gCache;
 
-static struct lastfm_config
+static struct scrobbler_cfg
 {
+    int  uniqct;
     int  savepct;
+    int  minms;
     int  beeplvl;
     bool playback;
     bool verbose;
@@ -108,16 +172,23 @@ static struct lastfm_config
 
 static struct configdata config[] =
 {
-   {TYPE_INT, 0, 100, { .int_p = &gConfig.savepct },   "SavePct",  NULL},
-   {TYPE_BOOL, 0, 1,  { .bool_p = &gConfig.playback }, "Playback", NULL},
-   {TYPE_BOOL, 0, 1,  { .bool_p = &gConfig.verbose },  "Verbose",  NULL},
-   {TYPE_INT, 0, 10,  { .int_p = &gConfig.beeplvl },   "BeepLvl",  NULL},
+    #define MAX_MRU (SCROBBLER_MAX_TRACK_MRU)
+    {TYPE_INT, 0, MAX_MRU, { .int_p = &gConfig.uniqct }, "UniqCt",  NULL},
+    {TYPE_INT, 0, 100, { .int_p = &gConfig.savepct },    "SavePct",  NULL},
+    {TYPE_INT, 0, 10000, { .int_p = &gConfig.minms },    "MinMs",    NULL},
+    {TYPE_BOOL, 0, 1,  { .bool_p = &gConfig.playback },  "Playback", NULL},
+    {TYPE_BOOL, 0, 1,  { .bool_p = &gConfig.verbose },   "Verbose",  NULL},
+    {TYPE_INT, 0, 10,  { .int_p = &gConfig.beeplvl },    "BeepLvl",  NULL},
+    #undef MAX_MRU
 };
 const int gCfg_sz = sizeof(config)/sizeof(*config);
+
 /****************** config functions *****************/
 static void config_set_defaults(void)
 {
+    gConfig.uniqct = SCROBBLER_MAX_TRACK_MRU;
     gConfig.savepct = 50;
+    gConfig.minms = 500;
     gConfig.playback = false;
     gConfig.verbose = true;
     gConfig.beeplvl = 10;
@@ -127,6 +198,8 @@ static int config_settings_menu(void)
 {
     int selection = 0;
 
+    static uint32_t crc = 0;
+
     struct viewport parentvp[NB_SCREENS];
     FOR_NB_SCREENS(l)
     {
@@ -134,48 +207,100 @@ static int config_settings_menu(void)
         rb->viewport_set_fullscreen(&parentvp[l], l);
     }
 
-    MENUITEM_STRINGLIST(settings_menu, ID2P(LANG_SETTINGS), NULL,
+    #define MENUITEM_STRINGLIST_CUSTOM(name, str, callback, ... )                  \
+        static const char *name##_[] = {__VA_ARGS__};                       \
+        static const struct menu_callback_with_desc name##__ =              \
+                {callback,str, Icon_NOICON};                                \
+        struct menu_item_ex name =                             \
+            {MT_RETURN_ID|MENU_HAS_DESC|                                    \
+             MENU_ITEM_COUNT(sizeof( name##_)/sizeof(*name##_)),            \
+                { .strings = name##_},{.callback_and_desc = & name##__}};
+
+    MENUITEM_STRINGLIST_CUSTOM(settings_menu, ID2P(LANG_SETTINGS), NULL,
                         ID2P(LANG_RESUME_PLAYBACK),
                         "Save Threshold",
+                        "Minimum Elapsed",
                         "Verbose",
                         "Beep Level",
+                        "Unique Track MRU",
+                        ID2P(LANG_REVERT_TO_DEFAULT_SETTINGS),
                         ID2P(VOICE_BLANK),
                         ID2P(LANG_CANCEL_0),
                         ID2P(LANG_SAVE_EXIT));
 
+    #undef MENUITEM_STRINGLIST_CUSTOM
+
+    const int items = MENU_GET_COUNT(settings_menu.flags);
+    const unsigned int flags = settings_menu.flags & (~MENU_ITEM_COUNT(MENU_COUNT_MASK));
+    if (crc == 0)
+    {
+        crc = rb->crc_32(&gConfig, sizeof(struct scrobbler_cfg), 0xFFFFFFFF);
+    }
+
     do {
+        if (crc == rb->crc_32(&gConfig, sizeof(struct scrobbler_cfg), 0xFFFFFFFF))
+        {
+            /* hide save item -- there are no changes to save */
+            settings_menu.flags = flags|MENU_ITEM_COUNT((items - 1));
+        }
+        else
+        {
+            settings_menu.flags = flags|MENU_ITEM_COUNT(items);
+        }
         selection=rb->do_menu(&settings_menu,&selection, parentvp, true);
         switch(selection) {
 
-            case 0:
-                rb->set_bool(str(LANG_RESUME_PLAYBACK), &gConfig.playback);
+            case 0: /* resume playback on plugin start */
+                rb->set_bool(rb->str(LANG_RESUME_PLAYBACK), &gConfig.playback);
                 break;
-            case 1:
+            case 1: /* % of track played to indicate listened status */
                 rb->set_int("Save Threshold", "%", UNIT_PERCENT,
                             &gConfig.savepct, NULL, 10, 0, 100, NULL );
                 break;
-            case 2:
+            case 2: /* tracks played less than this will not be logged */
+                rb->set_int("Minimum Elapsed", "ms", UNIT_MS,
+                            &gConfig.minms, NULL, 100, 0, 10000, NULL );
+                break;
+            case 3: /* suppress non-error messages */
                 rb->set_bool("Verbose", &gConfig.verbose);
                 break;
-            case 3:
+            case 4: /* set volume of start-up beep */
                 rb->set_int("Beep Level", "", UNIT_INT,
                             &gConfig.beeplvl, NULL, 1, 0, 10, NULL);
-                if (gConfig.beeplvl > 0)
-                    rb->beep_play(1500, 100, 100 * gConfig.beeplvl);
-            case 4: /*sep*/
+                play_tone(1500, 100);
+                break;
+            case 5: /* keep a list of tracks to prevent repeat [Skipped] entries */
+                rb->set_int("Unique Track MRU Size", "", UNIT_INT,
+                            &gConfig.uniqct, NULL, 1, 0, SCROBBLER_MAX_TRACK_MRU, NULL);
+                break;
+            case 6: /* set defaults */
+            {
+                const struct text_message prompt = {
+                    (const char*[]){ ID2P(LANG_AUDIOSCROBBLER),
+                                     ID2P(LANG_REVERT_TO_DEFAULT_SETTINGS)}, 2};
+                if(rb->gui_syncyesno_run(&prompt, NULL, NULL) == YESNO_YES)
+                {
+                    config_set_defaults();
+                    if (gConfig.verbose)
+                        rb->splash(HZ, ID2P(LANG_REVERT_TO_DEFAULT_SETTINGS));
+                }
+                break;
+            }
+            case 7: /*sep*/
                 continue;
-            case 5:
+            case 8: /* Cancel */
                 return -1;
                 break;
-            case 6:
+            case 9: /* Save & exit */
             {
                 int res = configfile_save(CFG_FILE, config, gCfg_sz, CFG_VER);
                 if (res >= 0)
                 {
-                    logf("Scrobbler cfg saved %s %d bytes", CFG_FILE, gCfg_sz);
+                    crc = rb->crc_32(&gConfig, sizeof(struct scrobbler_cfg), 0xFFFFFFFF);
+                    logf("SCROBBLER: cfg saved %s %d bytes", CFG_FILE, gCfg_sz);
                     return PLUGIN_OK;
                 }
-                logf("Scrobbler cfg FAILED (%d) %s", res, CFG_FILE);
+                logf("SCROBBLER: cfg FAILED (%d) %s", res, CFG_FILE);
                 return PLUGIN_ERROR;
             }
             case MENU_ATTACHED_USB:
@@ -188,12 +313,20 @@ static int config_settings_menu(void)
 }
 
 /****************** helper fuctions ******************/
+void play_tone(unsigned int frequency, unsigned int duration)
+{
+    if (gConfig.beeplvl > 0)
+        rb->beep_play(frequency, duration, 100 * gConfig.beeplvl);
+}
 
-int scrobbler_init(void)
+int scrobbler_init_cache(void)
 {
+    memset(&gCache, 0, sizeof(struct scrobbler_cache));
     gCache.buf = rb->plugin_get_buffer(&gCache.size);
 
-    size_t reqsz = SCROBBLER_MAX_CACHE*SCROBBLER_CACHE_LEN;
+    /* we need to reserve the space we want for our use in TSR plugins since
+     * someone else could call plugin_get_buffer() and corrupt our memory */
+    size_t reqsz = SCROBBLER_MAX_CACHE;
     gCache.size = PLUGIN_BUFFER_SIZE - rb->plugin_reserve_buffer(reqsz);
 
     if (gCache.size < reqsz)
@@ -201,14 +334,80 @@ int scrobbler_init(void)
         logf("SCROBBLER: OOM , %ld < req:%ld", gCache.size, reqsz);
         return -1;
     }
-
-    gCache.pos = 0;
-    gCache.pending = false;
     gCache.force_flush = true;
-    logf("Scrobbler Initialized");
+    rb->mutex_init(&gCache.mtx);
+    logf("SCROBBLER: Initialized");
     return 1;
 }
 
+static inline size_t cache_get_entry_size(int str_len)
+{
+    /* entry_sz consists of the cache entry + str_len + \0NULL terminator */
+    return str_len + 1 + sizeof(struct cache_entry);
+}
+
+static inline const char* str_chk_valid(const char *s, const char *alt)
+{
+    return (s != NULL ? s : alt);
+}
+
+static bool track_is_unique(uint32_t hash1, uint32_t hash2)
+{
+    bool is_unique = false;
+    static uint8_t mru_len = 0;
+
+    struct hash64 { uint32_t hash1; uint32_t hash2; };
+
+    static struct hash64 hash_mru[SCROBBLER_MAX_TRACK_MRU];
+    struct hash64 i = {0};
+    struct hash64 itmp;
+    uint8_t mru;
+
+    if (mru_len > gConfig.uniqct)
+        mru_len = gConfig.uniqct;
+
+    if (gConfig.uniqct < 1)
+        return true;
+
+    /* Search in MRU */
+    for (mru = 0; mru < mru_len; mru++)
+    {
+        /* Items shifted >> 1 */
+        itmp = i;
+        i = hash_mru[mru];
+            hash_mru[mru] = itmp;
+
+        /* Found in MRU */
+        if ((i.hash1 == hash1) && (i.hash2 == hash2))
+        {
+            logf("SCROBBLER: hash [%x, %x] found in MRU @ %d", i.hash1, i.hash2, mru);
+            goto Found;
+        }
+    }
+
+    /* Add MRU entry */
+    is_unique = true;
+    if (mru_len < SCROBBLER_MAX_TRACK_MRU && mru_len < gConfig.uniqct)
+    {
+        hash_mru[mru_len] = i;
+        mru_len++;
+    }
+    else
+    {
+        logf("SCROBBLER: hash [%x, %x] evicted from MRU", i.hash1, i.hash2);
+    }
+
+    i = (struct hash64){.hash1 = hash1, .hash2 = hash2};
+    logf("SCROBBLER: hash [%x, %x] added to  MRU[%d]", i.hash1, i.hash2, mru_len);
+
+Found:
+
+    /* Promote MRU item to top of MRU */
+    hash_mru[0] = i;
+
+    return is_unique;
+}
+
 static void get_scrobbler_filename(char *path, size_t size)
 {
     int used;
@@ -217,7 +416,7 @@ static void get_scrobbler_filename(char *path, size_t size)
 
     if (used >= (int)size)
     {
-        logf("%s: not enough buffer space for log file", __func__);
+        logf("%s: not enough buffer space for log filename", __func__);
         rb->memset(path, 0, size);
     }
 }
@@ -228,6 +427,9 @@ static void scrobbler_write_cache(void)
     int fd;
     logf("%s", __func__);
     char scrobbler_file[MAX_PATH];
+
+    rb->mutex_lock(&gCache.mtx);
+
     get_scrobbler_filename(scrobbler_file, sizeof(scrobbler_file));
 
     /* If the file doesn't exist, create it.
@@ -237,6 +439,7 @@ static void scrobbler_write_cache(void)
         fd = rb->open(scrobbler_file, O_RDWR | O_CREAT, 0666);
         if(fd >= 0)
         {
+            /* write file header */
             rb->fdprintf(fd, "#AUDIOSCROBBLER/" SCROBBLER_VERSION "\n"
                          "#TZ/UNKNOWN\n" "#CLIENT/Rockbox "
                          TARGET_NAME SCROBBLER_REVISION
@@ -251,38 +454,72 @@ static void scrobbler_write_cache(void)
         }
     }
 
+    int entries = gCache.entries;
+    size_t used = gCache.pos;
+    size_t pos = 0;
+    /* clear even if unsuccessful - we don't want to overflow the buffer */
+    gCache.pos = 0;
+    gCache.entries = 0;
+
     /* write the cache entries */
     fd = rb->open(scrobbler_file, O_WRONLY | O_APPEND);
     if(fd >= 0)
     {
-        logf("SCROBBLER: writing %d entries", gCache.pos);
-        /* copy data to temporary storage in case data moves during I/O */
-        char temp_buf[SCROBBLER_CACHE_LEN];
-        for ( i=0; i < gCache.pos; i++ )
+        logf("SCROBBLER: writing %d entries", entries);
+        /* copy cached data to storage */
+        uint32_t prev_crc = 0x0;
+        uint32_t crc;
+        size_t entry_sz, len;
+        bool err = false;
+
+        for (i = 0; i < entries && pos < used; i++)
         {
-            logf("SCROBBLER: write %d", i);
-            char* scrobbler_buf = gCache.buf;
-            ssize_t len = rb->strlcpy(temp_buf, scrobbler_buf+(SCROBBLER_CACHE_LEN*i),
-                                        sizeof(temp_buf));
-            if (rb->write(fd, temp_buf, len) != len)
+            logf("SCROBBLER: write %d read pos [%ld]", i, pos);
+
+            struct cache_entry *entry = (struct cache_entry*)&gCache.buf[pos];
+
+            entry_sz = cache_get_entry_size(entry->len);
+            crc = rb->crc_32(entry->buf, entry->len, 0xFFFFFFFF) ^ prev_crc;
+            prev_crc = crc;
+
+            len = rb->strlen(entry->buf);
+            logf("SCROBBLER: write entry %d sz [%ld] len [%ld]", i, entry_sz, len);
+
+            if (len != entry->len || crc != entry->crc) /* the entry is corrupted */
+            {
+                rb->write(fd, SCROBBLER_BAD_ENTRY, sizeof(SCROBBLER_BAD_ENTRY)-1);
+                logf("SCROBBLER: Bad entry %d", i);
+                if(!err)
+                {
+                    rb->queue_post(&gThread.queue, EV_USER_ERROR, ERR_WRITING_DATA);
+                    err = true;
+                }
+            }
+
+            logf("SCROBBLER: writing %s", entry->buf);
+
+            if (rb->write(fd, entry->buf, len) != (ssize_t)len)
                 break;
+
+            if (entry->buf[len - 1] != '\n')
+                rb->write(fd, "\n", 1); /* ensure newline termination */
+
+            pos += entry_sz;
         }
         rb->close(fd);
     }
     else
     {
         logf("SCROBBLER: error writing file");
+        rb->queue_post(&gThread.queue, EV_USER_ERROR, ERR_WRITING_FILE);
     }
-
-    /* clear even if unsuccessful - don't want to overflow the buffer */
-    gCache.pos = 0;
+    rb->mutex_unlock(&gCache.mtx);
 }
 
 #if USING_STORAGE_CALLBACK
 static void scrobbler_flush_callback(void)
 {
-    (void) gCache.force_flush;
-    if(gCache.pos <= 0)
+    if(gCache.pos == 0)
         return;
 #if (CONFIG_STORAGE & STORAGE_ATA)
     else
@@ -297,76 +534,127 @@ static void scrobbler_flush_callback(void)
 }
 #endif
 
-static inline char* str_chk_valid(char *s, char *alt)
-{
-    return (s != NULL ? s : alt);
-}
-
 static unsigned long scrobbler_get_threshold(unsigned long length)
 {
     /* length is assumed to be in miliseconds */
     return length / 100 * gConfig.savepct;
+}
+
+static int create_log_entry(const struct mp3entry *id,
+                        struct cache_entry *entry, int *trk_info_len)
+{
+    #define SEP "\t"
+    #define EOL "\n"
+    char* artist = id->artist ? id->artist : id->albumartist;
+    char rating = 'S'; /* Skipped */
+    if (id->elapsed >= scrobbler_get_threshold(id->length))
+        rating = 'L'; /* Listened */
 
+    char tracknum[11] = { "" };
+
+    if (id->tracknum > 0)
+        rb->snprintf(tracknum, sizeof (tracknum), "%d", id->tracknum);
+
+    int ret = rb->snprintf(entry->buf,
+                   SCROBBLER_CACHE_LEN,
+                   "%s"SEP"%s"SEP"%s"SEP"%s"SEP"%d%n"SEP"%c"SEP"%ld"SEP"%s"EOL"",
+                   str_chk_valid(artist, UNTAGGED),
+                   str_chk_valid(id->album, ""),
+                   str_chk_valid(id->title, id->path),
+                   tracknum,
+                   (int)(id->length / 1000),
+                   trk_info_len, /* receives len of the string written so far */
+                   rating,
+                   get_timestamp(),
+                   str_chk_valid(id->mb_track_id, ""));
+
+    #undef SEP
+    #undef EOL
+    return ret;
 }
 
 static void scrobbler_add_to_cache(const struct mp3entry *id)
 {
-    static uint32_t last_crc = 0;
     int trk_info_len = 0;
 
-    if ( gCache.pos >= SCROBBLER_MAX_CACHE )
-        scrobbler_write_cache();
+    if (id->elapsed < (unsigned long) gConfig.minms)
+    {
+        logf("SCROBBLER: skipping entry < %d ms: %s", gConfig.minms, id->path);
+        return;
+    }
 
-    char rating = 'S'; /* Skipped */
-    char* scrobbler_buf = gCache.buf;
+    rb->mutex_lock(&gCache.mtx);
 
-    logf("SCROBBLER: add_to_cache[%d]", gCache.pos);
+    /* not enough room left to guarantee next entry will fit so flush the cache */
+    if ( gCache.pos > SCROBBLER_MAX_CACHE - SCROBBLER_CACHE_LEN )
+        scrobbler_write_cache();
 
-    if (id->elapsed >= scrobbler_get_threshold(id->length))
-        rating = 'L'; /* Listened */
+    logf("SCROBBLER: add_to_cache[%d] write pos[%ld]", gCache.entries, gCache.pos);
+    /* use prev_crc to allow whole buffer to be checked for consistency */
+    static uint32_t prev_crc = 0x0;
+    if (gCache.pos == 0)
+        prev_crc = 0x0;
 
-    char tracknum[11] = { "" };
+    void *buf = &gCache.buf[gCache.pos];
+    memset(buf, 0, SCROBBLER_CACHE_LEN);
 
-    if (id->tracknum > 0)
-        rb->snprintf(tracknum, sizeof (tracknum), "%d", id->tracknum);
+    struct cache_entry *entry = buf;
 
-    char* artist = id->artist ? id->artist : id->albumartist;
+    int ret = create_log_entry(id, entry, &trk_info_len);
 
-    int ret = rb->snprintf(&scrobbler_buf[(SCROBBLER_CACHE_LEN*gCache.pos)],
-                       SCROBBLER_CACHE_LEN,
-                       "%s\t%s\t%s\t%s\t%d\t%c%n\t%ld\t%s\n",
-                       str_chk_valid(artist, UNTAGGED),
-                       str_chk_valid(id->album, ""),
-                       str_chk_valid(id->title, ""),
-                       tracknum,
-                       (int)(id->length / 1000),
-                       rating,
-                       &trk_info_len,
-                       get_timestamp(),
-                       str_chk_valid(id->mb_track_id, ""));
-
-    if ( ret >= SCROBBLER_CACHE_LEN )
+    if (ret <= 0 || (size_t) ret >= SCROBBLER_CACHE_LEN)
     {
         logf("SCROBBLER: entry too long:");
         logf("SCROBBLER: %s", id->path);
+        rb->queue_post(&gThread.queue, EV_USER_ERROR, ERR_ENTRY_LENGTH);
     }
-    else
+    else if (ret > 0)
     {
-        uint32_t crc = rb->crc_32(&scrobbler_buf[(SCROBBLER_CACHE_LEN*gCache.pos)],
-                                  trk_info_len, 0xFFFFFFFF);
-        if (crc != last_crc)
+        /* first generate a crc over the static portion of the track info data
+        this and a crc of the filename will be used to detect repeat entries
+        */
+        static uint32_t last_crc = 0;
+        uint32_t crc_entry = rb->crc_32(entry->buf, trk_info_len, 0xFFFFFFFF);
+        uint32_t crc_path = rb->crc_32(id->path, rb->strlen(id->path), 0xFFFFFFFF);
+        bool is_unique = track_is_unique(crc_entry, crc_path);
+        bool is_listened = (id->elapsed >= scrobbler_get_threshold(id->length));
+
+        if (is_unique || is_listened)
         {
-            last_crc = crc;
-            logf("Added %s", scrobbler_buf);
-            gCache.pos++;
+            /* finish calculating the CRC of the whole entry */
+            const void *src = entry->buf + trk_info_len;
+            entry->crc = rb->crc_32(src, ret - trk_info_len, crc_entry) ^ prev_crc;
+            prev_crc = entry->crc;
+            entry->len = ret;
+
+            /* since Listened entries are written regardless
+               make sure this isn't a direct repeat */
+            if ((entry->crc ^ crc_path) != last_crc)
+            {
+
+                if (is_listened)
+                    last_crc = (entry->crc ^ crc_path);
+                else
+                    last_crc = 0;
+
+                size_t entry_sz = cache_get_entry_size(ret);
+
+                logf("SCROBBLER: Added (#%d) sz[%ld] len[%d], %s",
+                     gCache.entries, entry_sz, ret, entry->buf);
+
+                gCache.entries++;
+                /* increase pos by string len + null terminator + sizeof entry */
+                gCache.pos += entry_sz;
+
 #if USING_STORAGE_CALLBACK
-            rb->register_storage_idle_func(scrobbler_flush_callback);
+                rb->register_storage_idle_func(scrobbler_flush_callback);
 #endif
+            }
         }
         else
             logf("SCROBBLER: skipping repeat entry: %s", id->path);
     }
-
+    rb->mutex_unlock(&gCache.mtx);
 }
 
 static void scrobbler_flush_cache(void)
@@ -387,16 +675,14 @@ static void scrobbler_flush_cache(void)
     }
 }
 
-static void scrobbler_change_event(unsigned short id, void *ev_data)
+static void track_change_event(unsigned short id, void *ev_data)
 {
     (void)id;
     logf("%s", __func__);
     struct mp3entry *id3 = ((struct track_event *)ev_data)->id3;
 
-    /*  check if track was resumed > %threshold played ( likely got saved )
-        check for blank artist or track name */
-    if ((id3->elapsed > scrobbler_get_threshold(id3->length))
-        || (!id3->artist && !id3->albumartist) || !id3->title)
+    /*  check if track was resumed > %threshold played ( likely got saved ) */
+    if ((id3->elapsed > scrobbler_get_threshold(id3->length)))
     {
         gCache.pending = false;
         logf("SCROBBLER: skipping file %s", id3->path);
@@ -408,6 +694,7 @@ static void scrobbler_change_event(unsigned short id, void *ev_data)
         gCache.pending = true;
     }
 }
+
 #ifdef ROCKBOX_HAS_LOGF
 static const char* track_event_info(struct track_event* te)
 {
@@ -422,12 +709,12 @@ static const char* track_event_info(struct track_event* te)
 * TEF_REWIND    = 0x4,   interpret as rewind, id3->elapsed is the
                              position before the seek back to 0
 */
-    logf("flag %d", te->flags);
+    logf("SCROBBLER: flag %d", te->flags);
    return strflags[te->flags&0x7];
 }
-
 #endif
-static void scrobbler_finish_event(unsigned short id, void *ev_data)
+
+static void track_finish_event(unsigned short id, void *ev_data)
 {
     (void)id;
     struct track_event *te = ((struct track_event *)ev_data);
@@ -439,22 +726,20 @@ static void scrobbler_finish_event(unsigned short id, void *ev_data)
 
         scrobbler_add_to_cache(te->id3);
     }
-
-
 }
 
 /****************** main thread + helpers ******************/
 static void events_unregister(void)
 {
     /* we don't want any more events */
-    rb->remove_event(PLAYBACK_EVENT_TRACK_CHANGE, scrobbler_change_event);
-    rb->remove_event(PLAYBACK_EVENT_TRACK_FINISH, scrobbler_finish_event);
+    rb->remove_event(PLAYBACK_EVENT_TRACK_CHANGE, track_change_event);
+    rb->remove_event(PLAYBACK_EVENT_TRACK_FINISH, track_finish_event);
 }
 
 static void events_register(void)
 {
-    rb->add_event(PLAYBACK_EVENT_TRACK_CHANGE, scrobbler_change_event);
-    rb->add_event(PLAYBACK_EVENT_TRACK_FINISH, scrobbler_finish_event);
+    rb->add_event(PLAYBACK_EVENT_TRACK_CHANGE, track_change_event);
+    rb->add_event(PLAYBACK_EVENT_TRACK_FINISH, track_finish_event);
 }
 
 void thread(void)
@@ -478,8 +763,7 @@ void thread(void)
                 /*fall through*/
             case EV_STARTUP:
                 events_register();
-                if (gConfig.beeplvl > 0)
-                    rb->beep_play(1500, 100, 100 * gConfig.beeplvl);
+                play_tone(1500, 100);
                 break;
             case SYS_POWEROFF:
             case SYS_REBOOT:
@@ -487,7 +771,7 @@ void thread(void)
                 /*fall through*/
             case EV_EXIT:
 #if USING_STORAGE_CALLBACK
-                rb->unregister_storage_idle_func(scrobbler_flush_callback, !in_usb);
+                rb->unregister_storage_idle_func(scrobbler_flush_callback, false);
 #else
                 if (!in_usb)
                     scrobbler_flush_cache();
@@ -498,6 +782,17 @@ void thread(void)
                 scrobbler_flush_cache();
                 rb->queue_reply(&gThread.queue, 0);
                 break;
+            case EV_USER_ERROR:
+                if (!in_usb)
+                {
+                    if (ev.data == ERR_WRITING_FILE)
+                        rb->splash(HZ, "SCROBBLER: error writing log");
+                    else if (ev.data == ERR_ENTRY_LENGTH)
+                        rb->splash(HZ, "SCROBBLER: error entry too long");
+                    else if (ev.data == ERR_WRITING_DATA)
+                        rb->splash(HZ, "SCROBBLER: error bad entry data");
+                }
+                break;
             default:
                 logf("default %ld", ev.id);
                 break;
@@ -507,7 +802,7 @@ void thread(void)
 
 void thread_create(void)
 {
-    /* put the thread's queue in the bcast list */
+    /* put the thread's queue in the broadcast list */
     rb->queue_init(&gThread.queue, true);
     gThread.id = rb->create_thread(thread, gThread.stack, sizeof(gThread.stack),
                                       0, "Last.Fm_TSR"
@@ -529,8 +824,8 @@ void thread_quit(void)
     }
 }
 
-/* callback to end the TSR plugin, called before a new one gets loaded */
-static int exit_tsr(bool reenter)
+/* callback to end the TSR plugin, called before a new plugin gets loaded */
+static int plugin_exit_tsr(bool reenter)
 {
     MENUITEM_STRINGLIST(menu, ID2P(LANG_AUDIOSCROBBLER), NULL, ID2P(LANG_SETTINGS),
                         "Flush Cache", "Exit Plugin", ID2P(LANG_BACK));
@@ -550,9 +845,12 @@ static int exit_tsr(bool reenter)
                 config_settings_menu();
                 break;
             case 1: /* flush cache */
-                rb->queue_send(&gThread.queue, EV_FLUSHCACHE, 0);
-                if (gConfig.verbose)
-                    rb->splashf(2*HZ, "%s Cache Flushed", str(LANG_AUDIOSCROBBLER));
+                if (gCache.entries > 0)
+                {
+                    rb->queue_send(&gThread.queue, EV_FLUSHCACHE, 0);
+                    if (gConfig.verbose)
+                        rb->splashf(2*HZ, "%s Cache Flushed", rb->str(LANG_AUDIOSCROBBLER));
+                }
                 break;
 
             case 2: /* exit plugin - quit */
@@ -572,13 +870,12 @@ static int exit_tsr(bool reenter)
 /****************** main ******************/
 static int plugin_main(const void* parameter)
 {
-    struct lastfm_config cfg;
-    rb->memcpy(&cfg, & gConfig, sizeof(struct lastfm_config));
+    struct scrobbler_cfg cfg;
+    rb->memcpy(&cfg, &gConfig, sizeof(struct scrobbler_cfg)); /* store settings */
 
-    /* Resume plugin ? */
+    /* Resume plugin ? -- silences startup */
     if (parameter == rb->plugin_tsr)
     {
-
         gConfig.beeplvl = 0;
         gConfig.playback = false;
         gConfig.verbose = false;
@@ -586,13 +883,13 @@ static int plugin_main(const void* parameter)
 
     rb->memset(&gThread, 0, sizeof(gThread));
     if (gConfig.verbose)
-        rb->splashf(HZ / 2, "%s Started",str(LANG_AUDIOSCROBBLER));
-    logf("%s: %s Started", __func__, str(LANG_AUDIOSCROBBLER));
+        rb->splashf(HZ / 2, "%s Started",rb->str(LANG_AUDIOSCROBBLER));
+    logf("%s: %s Started", __func__, rb->str(LANG_AUDIOSCROBBLER));
 
-    rb->plugin_tsr(exit_tsr); /* stay resident */
+    rb->plugin_tsr(plugin_exit_tsr); /* stay resident */
 
     thread_create();
-    rb->memcpy(&gConfig, &cfg, sizeof(struct lastfm_config));
+    rb->memcpy(&gConfig, &cfg, sizeof(struct scrobbler_cfg)); /*restore settings */
 
     if (gConfig.playback)
         return PLUGIN_GOTO_WPS;
@@ -607,8 +904,8 @@ enum plugin_status plugin_start(const void* parameter)
     /* now go ahead and have fun! */
     if (rb->usb_inserted() == true)
         return PLUGIN_USB_CONNECTED;
-    language_strings = rb->language_strings;
-    if (scrobbler_init() < 0)
+
+    if (scrobbler_init_cache() < 0)
         return PLUGIN_ERROR;
 
     config_set_defaults();
@@ -616,10 +913,9 @@ enum plugin_status plugin_start(const void* parameter)
     if (configfile_load(CFG_FILE, config, gCfg_sz, CFG_VER) < 0)
     {
         /* If the loading failed, save a new config file */
-        config_set_defaults();
         configfile_save(CFG_FILE, config, gCfg_sz, CFG_VER);
-
-        rb->splash(HZ, ID2P(LANG_REVERT_TO_DEFAULT_SETTINGS));
+        if (gConfig.verbose)
+            rb->splash(HZ, ID2P(LANG_REVERT_TO_DEFAULT_SETTINGS));
     }
 
     int ret = plugin_main(parameter);