Added trace statements through LFS_YES_TRACE

To use, compile and run with LFS_YES_TRACE defined:
make CFLAGS+=-DLFS_YES_TRACE=1 test_format

The name LFS_YES_TRACE was chosen to match the LFS_NO_DEBUG and
LFS_NO_WARN defines for the similar levels of output. The YES is
necessary to avoid a conflict with the actual LFS_TRACE macro that
gets emitting. LFS_TRACE can also be defined directly to provide
a custom trace formatter.

Hopefully having trace statements at the littlefs C API helps
debugging and reproducing issues.

Makefile

@@ -24,6 +24,9 @@ endif
 ifdef WORD
 override CFLAGS += -m$(WORD)
 endif
+ifdef TRACE
+override CFLAGS += -DLFS_YES_TRACE
+endif
 override CFLAGS += -I.
 override CFLAGS += -std=c99 -Wall -pedantic
 override CFLAGS += -Wextra -Wshadow -Wjump-misses-init

emubd/lfs_emubd.c

@@ -55,6 +55,15 @@ static inline void lfs_emubd_fromle32(lfs_emubd_t *emu) {
 
 // Block device emulated on existing filesystem
 int lfs_emubd_create(const struct lfs_config *cfg, const char *path) {
+    LFS_TRACE("lfs_emubd_create(%p {.context=%p, "
+                ".read=%p, .prog=%p, .erase=%p, .sync=%p, "
+                ".read_size=%"PRIu32", .prog_size=%"PRIu32", "
+                ".block_size=%"PRIu32", .block_count=%"PRIu32"}, \"%s\")",
+            (void*)cfg, cfg->context,
+            (void*)(uintptr_t)cfg->read, (void*)(uintptr_t)cfg->prog,
+            (void*)(uintptr_t)cfg->erase, (void*)(uintptr_t)cfg->sync,
+            cfg->read_size, cfg->prog_size, cfg->block_size, cfg->block_count,
+            path);
     lfs_emubd_t *emu = cfg->context;
     emu->cfg.read_size   = cfg->read_size;
     emu->cfg.prog_size   = cfg->prog_size;
@@ -65,7 +74,9 @@ int lfs_emubd_create(const struct lfs_config *cfg, const char *path) {
     size_t pathlen = strlen(path);
     emu->path = malloc(pathlen + 1 + LFS_NAME_MAX + 1);
     if (!emu->path) {
-        return -ENOMEM;
+        int err = -ENOMEM;
+        LFS_TRACE("lfs_emubd_create -> %"PRId32, err);
+        return err;
     }
 
     strcpy(emu->path, path);
@@ -76,7 +87,9 @@ int lfs_emubd_create(const struct lfs_config *cfg, const char *path) {
     // Create directory if it doesn't exist
     int err = mkdir(path, 0777);
     if (err && errno != EEXIST) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_create -> %"PRId32, err);
+        return err;
     }
 
     // Load stats to continue incrementing
@@ -88,12 +101,16 @@ int lfs_emubd_create(const struct lfs_config *cfg, const char *path) {
         size_t res = fread(&emu->stats, sizeof(emu->stats), 1, f);
         lfs_emubd_fromle32(emu);
         if (res < 1) {
-            return -errno;
+            err = -errno;
+            LFS_TRACE("lfs_emubd_create -> %"PRId32, err);
+            return err;
         }
 
         err = fclose(f);
         if (err) {
-            return -errno;
+            err = -errno;
+            LFS_TRACE("lfs_emubd_create -> %"PRId32, err);
+            return err;
         }
     }
 
@@ -106,27 +123,36 @@ int lfs_emubd_create(const struct lfs_config *cfg, const char *path) {
         size_t res = fread(&emu->history, sizeof(emu->history), 1, f);
         lfs_emubd_fromle32(emu);
         if (res < 1) {
-            return -errno;
+            err = -errno;
+            LFS_TRACE("lfs_emubd_create -> %"PRId32, err);
+            return err;
         }
 
         err = fclose(f);
         if (err) {
-            return -errno;
+            err = -errno;
+            LFS_TRACE("lfs_emubd_create -> %"PRId32, err);
+            return err;
         }
     }
 
+    LFS_TRACE("lfs_emubd_create -> %"PRId32, 0);
     return 0;
 }
 
 void lfs_emubd_destroy(const struct lfs_config *cfg) {
+    LFS_TRACE("lfs_emubd_destroy(%p)", (void*)cfg);
     lfs_emubd_sync(cfg);
 
     lfs_emubd_t *emu = cfg->context;
     free(emu->path);
+    LFS_TRACE("lfs_emubd_destroy -> %s", "void");
 }
 
 int lfs_emubd_read(const struct lfs_config *cfg, lfs_block_t block,
         lfs_off_t off, void *buffer, lfs_size_t size) {
+    LFS_TRACE("lfs_emubd_read(%p, %"PRIu32", %"PRIu32", %p, %"PRIu32")",
+            (void*)cfg, block, off, buffer, size);
     lfs_emubd_t *emu = cfg->context;
     uint8_t *data = buffer;
 
@@ -143,32 +169,43 @@ int lfs_emubd_read(const struct lfs_config *cfg, lfs_block_t block,
 
     FILE *f = fopen(emu->path, "rb");
     if (!f && errno != ENOENT) {
-        return -errno;
+        int err = -errno;
+        LFS_TRACE("lfs_emubd_read -> %d", err);
+        return err;
     }
 
     if (f) {
         int err = fseek(f, off, SEEK_SET);
         if (err) {
-            return -errno;
+            err = -errno;
+            LFS_TRACE("lfs_emubd_read -> %d", err);
+            return err;
         }
 
         size_t res = fread(data, 1, size, f);
         if (res < size && !feof(f)) {
-            return -errno;
+            err = -errno;
+            LFS_TRACE("lfs_emubd_read -> %d", err);
+            return err;
         }
 
         err = fclose(f);
         if (err) {
-            return -errno;
+            err = -errno;
+            LFS_TRACE("lfs_emubd_read -> %d", err);
+            return err;
         }
     }
 
     emu->stats.read_count += 1;
+    LFS_TRACE("lfs_emubd_read -> %d", 0);
     return 0;
 }
 
 int lfs_emubd_prog(const struct lfs_config *cfg, lfs_block_t block,
         lfs_off_t off, const void *buffer, lfs_size_t size) {
+    LFS_TRACE("lfs_emubd_prog(%p, %"PRIu32", %"PRIu32", %p, %"PRIu32")",
+            (void*)cfg, block, off, buffer, size);
     lfs_emubd_t *emu = cfg->context;
     const uint8_t *data = buffer;
 
@@ -182,7 +219,9 @@ int lfs_emubd_prog(const struct lfs_config *cfg, lfs_block_t block,
 
     FILE *f = fopen(emu->path, "r+b");
     if (!f) {
-        return (errno == EACCES) ? 0 : -errno;
+        int err = (errno == EACCES) ? 0 : -errno;
+        LFS_TRACE("lfs_emubd_prog -> %d", err);
+        return err;
     }
 
     // Check that file was erased
@@ -190,28 +229,38 @@ int lfs_emubd_prog(const struct lfs_config *cfg, lfs_block_t block,
 
     int err = fseek(f, off, SEEK_SET);
     if (err) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_prog -> %d", err);
+        return err;
     }
 
     size_t res = fwrite(data, 1, size, f);
     if (res < size) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_prog -> %d", err);
+        return err;
     }
 
     err = fseek(f, off, SEEK_SET);
     if (err) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_prog -> %d", err);
+        return err;
     }
 
     uint8_t dat;
     res = fread(&dat, 1, 1, f);
     if (res < 1) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_prog -> %d", err);
+        return err;
     }
 
     err = fclose(f);
     if (err) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_prog -> %d", err);
+        return err;
     }
 
     // update history and stats
@@ -222,10 +271,12 @@ int lfs_emubd_prog(const struct lfs_config *cfg, lfs_block_t block,
     }
 
     emu->stats.prog_count += 1;
+    LFS_TRACE("lfs_emubd_prog -> %d", 0);
     return 0;
 }
 
 int lfs_emubd_erase(const struct lfs_config *cfg, lfs_block_t block) {
+    LFS_TRACE("lfs_emubd_erase(%p, %"PRIu32")", (void*)cfg, block);
     lfs_emubd_t *emu = cfg->context;
 
     // Check if erase is valid
@@ -236,89 +287,118 @@ int lfs_emubd_erase(const struct lfs_config *cfg, lfs_block_t block) {
     struct stat st;
     int err = stat(emu->path, &st);
     if (err && errno != ENOENT) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_erase -> %d", err);
+        return err;
     }
 
     if (!err && S_ISREG(st.st_mode) && (S_IWUSR & st.st_mode)) {
         err = unlink(emu->path);
         if (err) {
-            return -errno;
+            err = -errno;
+            LFS_TRACE("lfs_emubd_erase -> %d", err);
+            return err;
         }
     }
 
     if (err || (S_ISREG(st.st_mode) && (S_IWUSR & st.st_mode))) {
         FILE *f = fopen(emu->path, "w");
         if (!f) {
-            return -errno;
+            err = -errno;
+            LFS_TRACE("lfs_emubd_erase -> %d", err);
+            return err;
         }
 
         err = fclose(f);
         if (err) {
-            return -errno;
+            err = -errno;
+            LFS_TRACE("lfs_emubd_erase -> %d", err);
+            return err;
         }
     }
 
     emu->stats.erase_count += 1;
+    LFS_TRACE("lfs_emubd_erase -> %d", 0);
     return 0;
 }
 
 int lfs_emubd_sync(const struct lfs_config *cfg) {
+    LFS_TRACE("lfs_emubd_sync(%p)", (void*)cfg);
     lfs_emubd_t *emu = cfg->context;
 
     // Just write out info/stats for later lookup
     snprintf(emu->child, LFS_NAME_MAX, ".config");
     FILE *f = fopen(emu->path, "w");
     if (!f) {
-        return -errno;
+        int err = -errno;
+        LFS_TRACE("lfs_emubd_sync -> %d", err);
+        return err;
     }
 
     lfs_emubd_tole32(emu);
     size_t res = fwrite(&emu->cfg, sizeof(emu->cfg), 1, f);
     lfs_emubd_fromle32(emu);
     if (res < 1) {
-        return -errno;
+        int err = -errno;
+        LFS_TRACE("lfs_emubd_sync -> %d", err);
+        return err;
     }
 
     int err = fclose(f);
     if (err) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_sync -> %d", err);
+        return err;
     }
 
     snprintf(emu->child, LFS_NAME_MAX, ".stats");
     f = fopen(emu->path, "w");
     if (!f) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_sync -> %d", err);
+        return err;
     }
 
     lfs_emubd_tole32(emu);
     res = fwrite(&emu->stats, sizeof(emu->stats), 1, f);
     lfs_emubd_fromle32(emu);
     if (res < 1) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_sync -> %d", err);
+        return err;
     }
 
     err = fclose(f);
     if (err) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_sync -> %d", err);
+        return err;
     }
 
     snprintf(emu->child, LFS_NAME_MAX, ".history");
     f = fopen(emu->path, "w");
     if (!f) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_sync -> %d", err);
+        return err;
     }
 
     lfs_emubd_tole32(emu);
     res = fwrite(&emu->history, sizeof(emu->history), 1, f);
     lfs_emubd_fromle32(emu);
     if (res < 1) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_sync -> %d", err);
+        return err;
     }
 
     err = fclose(f);
     if (err) {
-        return -errno;
+        err = -errno;
+        LFS_TRACE("lfs_emubd_sync -> %d", err);
+        return err;
     }
 
+    LFS_TRACE("lfs_emubd_sync -> %d", 0);
     return 0;
 }

lfs_util.h

@@ -31,7 +31,10 @@
 #ifndef LFS_NO_ASSERT
 #include <assert.h>
 #endif
-#if !defined(LFS_NO_DEBUG) || !defined(LFS_NO_WARN) || !defined(LFS_NO_ERROR)
+#if !defined(LFS_NO_DEBUG) || \
+        !defined(LFS_NO_WARN) || \
+        !defined(LFS_NO_ERROR) || \
+        defined(LFS_YES_TRACE)
 #include <stdio.h>
 #endif
 
@@ -46,6 +49,13 @@ extern "C"
 // code footprint
 
 // Logging functions
+#ifdef LFS_YES_TRACE
+#define LFS_TRACE(fmt, ...) \
+    printf("lfs trace:%d: " fmt "\n", __LINE__, __VA_ARGS__)
+#else
+#define LFS_TRACE(fmt, ...)
+#endif
+
 #ifndef LFS_NO_DEBUG
 #define LFS_DEBUG(fmt, ...) \
     printf("lfs debug:%d: " fmt "\n", __LINE__, __VA_ARGS__)