log library refactoring, first steps

src/gamecode/laws.c

@@ -3998,7 +3998,7 @@ void process(void)
       printf("- Step %u\n", prio);
     while (proc && proc->priority == prio) {
       if (proc->name && verbosity >= 1)
-        log_stdio(stdout, " - %s\n", proc->name);
+        log_printf(stdout, " - %s\n", proc->name);
       proc = proc->next;
     }
 

src/gamecode/randenc.c

@@ -1137,7 +1137,7 @@ static void demon_skillchanges(void)
             }
             if (sv->old > sv->level) {
               if (verbosity >= 3) {
-                log_printf("%s dropped from %u to %u:%u in %s\n",
+                log_printf(stdout, "%s dropped from %u to %u:%u in %s\n",
                   unitname(u), sv->old, sv->level, sv->weeks, skillname(sv->id,
                     NULL));
               }

src/kernel/battle.c

@@ -3814,7 +3814,7 @@ static int battle_report(battle * b)
   }
 
   if (verbosity > 0)
-    log_stdio(stdout, " %d", b->turn);
+    log_printf(stdout, " %d", b->turn);
   fflush(stdout);
 
   for (bf = b->factions; bf; bf = bf->next) {
@@ -4493,7 +4493,7 @@ void do_battle(region * r)
 
   print_stats(b);               /* gibt die Kampfaufstellung aus */
   if (verbosity > 0)
-    log_stdio(stdout, "%s (%d, %d) : ", rname(r, default_locale), r->x, r->y);
+    log_printf(stdout, "%s (%d, %d) : ", rname(r, default_locale), r->x, r->y);
 
   for (; battle_report(b) && b->turn <= max_turns; ++b->turn) {
     if (bdebug) {
@@ -4506,7 +4506,7 @@ void do_battle(region * r)
   }
 
   if (verbosity > 0)
-    log_stdio(stdout, "\n");
+    log_printf(stdout, "\n");
 
   /* Auswirkungen berechnen: */
   aftermath(b);

src/kernel/config.c

@@ -611,7 +611,7 @@ int count_skill(faction * f, skill_t sk)
   return n;
 }
 
-int verbosity = 0;
+int verbosity = 1;
 
 FILE *debug;
 
@@ -743,7 +743,7 @@ void verify_data(void)
       if (u->number > UNIT_MAXSIZE) {
         if (lf != f->no) {
           lf = f->no;
-          log_stdio(stdout, "Partei %s:\n", factionid(f));
+          log_printf(stdout, "Partei %s:\n", factionid(f));
         }
         log_warning(("Einheit %s hat %d Personen\n", unitid(u), u->number));
       }
@@ -2364,7 +2364,7 @@ void remove_empty_factions(void)
       while (ur && ur->id != 0)
         ur = ur->next;
       if (verbosity >= 2)
-        log_stdio(stdout, "\t%s\n", factionname(f));
+        log_printf(stdout, "\t%s\n", factionname(f));
 
       /* Einfach in eine Datei schreiben und später vermailen */
 

src/kernel/reports.c

@@ -1521,7 +1521,7 @@ int write_reports(faction * f, time_t ltime)
 
     errno = 0;
     if (verbosity >= 2) {
-      log_stdio(stdout, "Reports for %s:", factionname(f));
+      log_printf(stdout, "Reports for %s:", factionname(f));
     }
     for (; rtype != NULL; rtype = rtype->next) {
       if (f->options & rtype->flag) {
@@ -1660,7 +1660,7 @@ int reports(void)
   char path[MAX_PATH];
 
   if (verbosity >= 1) {
-    log_stdio(stdout, "Writing reports for turn %d:", turn);
+    log_printf(stdout, "Writing reports for turn %d:", turn);
   }
   nmr_warnings();
   report_donations();
@@ -2207,7 +2207,7 @@ static void log_orders(const struct message *msg)
     if (msg->type->types[i]->copy == &var_copy_order) {
       const char *section = nr_section(msg);
       nr_render(msg, f ? f->locale : default_locale, buffer, sizeof(buffer), f);
-      log_printf("MESSAGE [%s]: %s\n", section, buffer);
+      log_debug("MESSAGE [%s]: %s\n", section, buffer);
       break;
     }
   }

src/kernel/save.c

@@ -462,7 +462,7 @@ int readorders(const char *filename)
   fclose(F);
   if (verbosity >= 1)
     puts("\n");
-  log_printf("   %d Befehlsdateien gelesen\n", nfactions);
+  log_printf(stdout, "   %d Befehlsdateien gelesen\n", nfactions);
   return 0;
 }
 
@@ -1234,7 +1234,7 @@ faction *readfaction(struct storage * store)
   f->name = store->r_str(store);
   f->banner = store->r_str(store);
 
-  log_info((3, "   - Lese Partei %s (%s)\n", f->name, factionid(f)));
+  log_printf(stdout, "   - Lese Partei %s (%s)\n", f->name, factionid(f));
 
   store->r_str_buf(store, email, sizeof(email));
   if (set_email(&f->email, email) != 0) {
@@ -1433,7 +1433,7 @@ int readgame(const char *filename, int mode, int backup)
   storage *store = &my_store;
 
   sprintf(path, "%s/%s", datapath(), filename);
-  log_printf("- reading game data from %s\n", filename);
+  log_printf(stdout, "- reading game data from %s\n", filename);
   if (backup)
     create_backup(path);
 
@@ -1463,7 +1463,7 @@ int readgame(const char *filename, int mode, int backup)
   }
   a_read(store, &global.attribs, NULL);
   global.data_turn = turn = store->r_int(store);
-  log_info((1, " - reading turn %d\n", turn));
+  log_printf(stdout, " - reading turn %d\n", turn);
   rng_init(turn);
   ++global.cookie;
   store->r_int(store);          /* max_unique_id = */
@@ -1523,7 +1523,7 @@ int readgame(const char *filename, int mode, int backup)
     read_alliances(store);
   }
   n = store->r_int(store);
-  log_info((1, " - Einzulesende Parteien: %d\n", n));
+  log_printf(stdout, " - Einzulesende Parteien: %d\n", n);
   fp = &factions;
   while (*fp)
     fp = &(*fp)->next;
@@ -1551,15 +1551,14 @@ int readgame(const char *filename, int mode, int backup)
   assert(n < MAXREGIONS);
   if (rmax < 0)
     rmax = n;
-  log_info((1, " - Einzulesende Regionen: %d/%d\r", rmax, n));
+  log_printf(stdout, " - Einzulesende Regionen: %d/%d\r", rmax, n);
   while (--n >= 0) {
     unit **up;
     int x = store->r_int(store);
     int y = store->r_int(store);
 
     if ((n & 0x3FF) == 0) {     /* das spart extrem Zeit */
-      log_info((2, " - Einzulesende Regionen: %d/%d * %d,%d    \r", rmax, n, x,
+      log_printf(stdout, " - Einzulesende Regionen: %d/%d * %d,%d    \r", rmax, n, x, y);
-          y));
     }
     --rmax;
 
@@ -1668,16 +1667,16 @@ int readgame(const char *filename, int mode, int backup)
       }
     }
   }
-  log_info((1, "\n"));
+  log_printf(stdout, "\n");
   read_borders(store);
 
   store->close(store);
 
   /* Unaufgeloeste Zeiger initialisieren */
-  log_info((1, "fixing unresolved references.\n"));
+  log_printf(stdout, "fixing unresolved references.\n");
   resolve();
 
-  log_info((1, "updating area information for lighthouses.\n"));
+  log_printf(stdout, "updating area information for lighthouses.\n");
   for (r = regions; r; r = r->next) {
     if (r->flags & RF_LIGHTHOUSE) {
       building *b;
@@ -1685,7 +1684,7 @@ int readgame(const char *filename, int mode, int backup)
         update_lighthouse(b);
     }
   }
-  log_info((1, "marking factions as alive.\n"));
+  log_printf(stdout, "marking factions as alive.\n");
   for (f = factions; f; f = f->next) {
     if (f->flags & FFL_NPC) {
       f->alive = 1;
@@ -1708,7 +1707,7 @@ int readgame(const char *filename, int mode, int backup)
   if (loadplane || maxregions >= 0) {
     remove_empty_factions();
   }
-  log_info((1, "Done loading turn %d.\n", turn));
+  log_printf(stdout, "Done loading turn %d.\n", turn);
   return 0;
 }
 
@@ -1809,7 +1808,7 @@ int writegame(const char *filename, int mode)
   store->w_int(store, n);
   store->w_brk(store);
 
-  log_info((1, " - Schreibe %d Parteien...\n", n));
+  log_printf(stdout, " - Schreibe %d Parteien...\n", n);
   for (f = factions; f; f = f->next) {
     writefaction(store, f);
     store->w_brk(store);
@@ -1820,12 +1819,12 @@ int writegame(const char *filename, int mode)
   n = listlen(regions);
   store->w_int(store, n);
   store->w_brk(store);
-  log_info((1, " - Schreibe Regionen: %d  \r", n));
+  log_printf(stdout, " - Schreibe Regionen: %d  \r", n);
 
   for (r = regions; r; r = r->next, --n) {
     /* plus leerzeile */
     if ((n % 1024) == 0) {      /* das spart extrem Zeit */
-      log_info((2, " - Schreibe Regionen: %d  \r", n));
+      log_printf(stdout, " - Schreibe Regionen: %d  \r", n);
       fflush(stdout);
     }
     store->w_brk(store);
@@ -1876,7 +1875,7 @@ int writegame(const char *filename, int mode)
 
   store->close(store);
 
-  log_info((1, "\nOk.\n"));
+  log_printf(stdout, "\nOk.\n");
   return 0;
 }
 

src/modules/autoseed.c

@@ -688,7 +688,7 @@ int autoseed(newfaction ** players, int nsize, int max_agediff)
       f = u->faction;
       fset(f, FFL_ISNEW);
       f->alliance = nextf->allies;
-      log_printf("New faction (%s), %s at %s\n", itoa36(f->no),
+      log_printf(stdout, "New faction (%s), %s at %s\n", itoa36(f->no),
         f->email, regionname(r, NULL));
       if (f->subscription) {
         sql_print(

src/util/listbox.c

@@ -82,21 +82,23 @@ list_selection *do_selection(list_selection * sel, const char *title,
   int i;
   int height = 0, width = (int)strlen(title) + 8;
   for (s = sel; s; s = s->next) {
-    if ((int)strlen(s->str) > width)
+    if ((int)strlen(s->str) > width) {
       width = (int)strlen(s->str);
+    }
     ++height;
-    if (verbosity >= 5)
+    if (verbosity >= 5) {
-      log_info((1, "s %s w %d h %d\n", s->str, width, height));
+      log_printf(stdout, "s %s w %d h %d\n", s->str, width, height);
+    }
   }
   if (height == 0 || width == 0)
-    return NULL;
+    return 0;
   if (width + 3 > SX)
     width = SX - 4;
   if (height + 2 > SY)
     height = SY - 2;
 
   if (verbosity >= 5)
-    log_info((1, "w %d h %d\n", width, height));
+    log_printf(stdout, "w %d h %d\n", width, height);
 
   wn =
     newwin(height + 2, width + 4, (SY - height - 2) / 2, (SX - width - 4) / 2);

src/util/log.c

@@ -21,6 +21,8 @@ without prior permission by the authors of Eressea.
 
 /* TODO: set from external function */
 int log_flags = LOG_FLUSH | LOG_CPERROR | LOG_CPWARNING | LOG_CPDEBUG;
+int log_stderr = LOG_FLUSH | LOG_CPERROR | LOG_CPWARNING;
+
 #ifdef STDIO_CP
 static int stdio_codepage = STDIO_CP;
 #else
@@ -37,9 +39,9 @@ void log_flush(void)
 void log_puts(const char *str)
 {
   fflush(stdout);
-  if (!logfile)
+  if (logfile) {
-    logfile = stderr;
+    fputs(str, logfile);
-  fputs(str, logfile);
+  }
 }
 
 static int
@@ -68,47 +70,6 @@ cp_convert(const char *format, char *buffer, size_t length, int codepage)
   return 0;
 }
 
-void log_printf(const char *format, ...)
-{
-  va_list marker;
-  if (!logfile)
-    logfile = stderr;
-  va_start(marker, format);
-  vfprintf(logfile, format, marker);
-  va_end(marker);
-  if (log_flags & LOG_FLUSH) {
-    log_flush();
-  }
-}
-
-void log_stdio(FILE * io, const char *format, ...)
-{
-  va_list marker;
-  if (!logfile)
-    logfile = stderr;
-  va_start(marker, format);
-  if (stdio_codepage) {
-    char buffer[MAXLENGTH];
-    char converted[MAXLENGTH];
-
-    vsnprintf(buffer, sizeof(buffer), format, marker);
-    if (cp_convert(buffer, converted, MAXLENGTH, stdio_codepage) == 0) {
-      fputs(converted, stderr);
-    } else {
-      /* fall back to non-converted output */
-      va_end(marker);
-      va_start(marker, format);
-      vfprintf(io, format, marker);
-    }
-  } else {
-    vfprintf(io, format, marker);
-  }
-  va_end(marker);
-  if (log_flags & LOG_FLUSH) {
-    log_flush();
-  }
-}
-
 void log_open(const char *filename)
 {
   if (logfile)
@@ -118,7 +79,7 @@ void log_open(const char *filename)
     /* Get UNIX-style time and display as number and string. */
     time_t ltime;
     time(&ltime);
-    log_printf("===\n=== Logfile started at %s===\n", ctime(&ltime));
+    fprintf(logfile, "===\n=== Logfile started at %s===\n", ctime(&ltime));
   }
 }
 
@@ -130,9 +91,9 @@ void log_close(void)
     /* Get UNIX-style time and display as number and string. */
     time_t ltime;
     time(&ltime);
-    log_printf("===\n=== Logfile closed at %s===\n\n", ctime(&ltime));
+    fprintf(logfile, "===\n=== Logfile closed at %s===\n\n", ctime(&ltime));
+    fclose(logfile);
   }
-  fclose(logfile);
   logfile = 0;
 }
 
@@ -157,175 +118,165 @@ static int check_dupe(const char *format, const char *type)
   return 0;
 }
 
+static void _log_write(FILE * stream, int codepage, const char * prefix, const char *format, va_list args)
+{
+  if (stream) {
+    fprintf(stream, "%s: ", prefix);
+    if (codepage) {
+      char buffer[MAXLENGTH];
+      char converted[MAXLENGTH];
+      
+      vsnprintf(buffer, sizeof(buffer), format, args);
+      if (cp_convert(buffer, converted, MAXLENGTH, codepage) == 0) {
+        fputs(converted, stream);
+      } else {
+        /* fall back to non-converted output */
+        vfprintf(stream, format, args);
+      }
+    } else {
+      vfprintf(stream, format, args);
+    }
+  }
+}
+
 void _log_debug(const char *format, ...)
 {
-  if (log_flags & LOG_CPDEBUG) {
+  const char * prefix = "DEBUG";
-    int dupe = check_dupe(format, "DEBUG");
+  const int mask = LOG_CPDEBUG;
 
-    fflush(stdout);
+  /* write to the logfile, always */
-    if (!logfile)
+  if (logfile && (log_flags & mask)) {
-      logfile = stderr;
+    va_list args;
-    if (logfile != stderr) {
+    va_start(args, format);
-      va_list marker;
+    _log_write(logfile, 0, prefix, format, args);
-      fputs("DEBUG: ", logfile);
+    va_end(args);
-      va_start(marker, format);
+  }
-      vfprintf(logfile, format, marker);
+
-      va_end(marker);
+  /* write to stderr, if that's not the logfile already */
-    }
+  if (logfile!=stderr && (log_stderr & mask)) {
+    int dupe = check_dupe(format, prefix);
     if (!dupe) {
-      va_list marker;
+      va_list args;
-      fputs("DEBUG: ", stderr);
+      va_start(args, format);
-      va_start(marker, format);
+      _log_write(stderr, stdio_codepage, prefix, format, args);
-      if (stdio_codepage) {
+      va_end(args);
-        char buffer[MAXLENGTH];
-        char converted[MAXLENGTH];
-
-        vsnprintf(buffer, sizeof(buffer), format, marker);
-        if (cp_convert(buffer, converted, MAXLENGTH, stdio_codepage) == 0) {
-          fputs(converted, stderr);
-        } else {
-          /* fall back to non-converted output */
-          va_end(marker);
-          va_start(marker, format);
-          vfprintf(stderr, format, marker);
-        }
-      } else {
-        vfprintf(stderr, format, marker);
-      }
-      va_end(marker);
-    }
-    if (log_flags & LOG_FLUSH) {
-      log_flush();
     }
   }
+  if (log_flags & LOG_FLUSH) {
+    log_flush();
+  }
 }
 
 void _log_warn(const char *format, ...)
 {
-  if (log_flags & LOG_CPWARNING) {
+  const char * prefix = "WARNING";
-    int dupe = check_dupe(format, "WARNING");
+  const int mask = LOG_CPWARNING;
 
-    fflush(stdout);
+  /* write to the logfile, always */
-    if (!logfile)
+  if (logfile && (log_flags & mask)) {
-      logfile = stderr;
+    va_list args;
-    if (logfile != stderr) {
+    va_start(args, format);
-      va_list marker;
+    _log_write(logfile, 0, prefix, format, args);
-      fputs("WARNING: ", logfile);
+    va_end(args);
-      va_start(marker, format);
+  }
-      vfprintf(logfile, format, marker);
+
-      va_end(marker);
+  /* write to stderr, if that's not the logfile already */
-    }
+  if (logfile!=stderr && (log_stderr & mask)) {
+    int dupe = check_dupe(format, prefix);
     if (!dupe) {
-      va_list marker;
+      va_list args;
-      fputs("WARNING: ", stderr);
+      va_start(args, format);
-      va_start(marker, format);
+      _log_write(stderr, stdio_codepage, prefix, format, args);
-      if (stdio_codepage) {
+      va_end(args);
-        char buffer[MAXLENGTH];
-        char converted[MAXLENGTH];
-
-        vsnprintf(buffer, sizeof(buffer), format, marker);
-        if (cp_convert(buffer, converted, MAXLENGTH, stdio_codepage) == 0) {
-          fputs(converted, stderr);
-        } else {
-          /* fall back to non-converted output */
-          va_end(marker);
-          va_start(marker, format);
-          vfprintf(stderr, format, marker);
-        }
-      } else {
-        vfprintf(stderr, format, marker);
-      }
-      va_end(marker);
-    }
-    if (log_flags & LOG_FLUSH) {
-      log_flush();
     }
   }
+  if (log_flags & LOG_FLUSH) {
+    log_flush();
+  }
 }
 
 void _log_error(const char *format, ...)
 {
-  int dupe = check_dupe(format, "ERROR");
+  const char * prefix = "ERROR";
-  fflush(stdout);
+  const int mask = LOG_CPERROR;
-  if (!logfile)
-    logfile = stderr;
 
-  if (logfile != stderr) {
+  /* write to the logfile, always */
-    va_list marker;
+  if (logfile && (log_flags & mask)) {
-    fputs("ERROR: ", logfile);
+    va_list args;
-    va_start(marker, format);
+    va_start(args, format);
-    vfprintf(logfile, format, marker);
+    _log_write(logfile, 0, prefix, format, args);
-    va_end(marker);
+    va_end(args);
   }
-  if (!dupe) {
-    if (logfile != stderr) {
-      if (log_flags & LOG_CPERROR) {
-        va_list marker;
 
-        fputs("ERROR: ", stderr);
+  /* write to stderr, if that's not the logfile already */
-        va_start(marker, format);
+  if (logfile!=stderr && (log_stderr & mask)) {
-        if (stdio_codepage) {
+    int dupe = check_dupe(format, prefix);
-          char buffer[MAXLENGTH];
+    if (!dupe) {
-          char converted[MAXLENGTH];
+      va_list args;
-
+      va_start(args, format);
-          vsnprintf(buffer, sizeof(buffer), format, marker);
+      _log_write(stderr, stdio_codepage, prefix, format, args);
-          if (cp_convert(buffer, converted, MAXLENGTH, stdio_codepage) == 0) {
+      va_end(args);
-            fputs(converted, stderr);
-          } else {
-            /* fall back to non-converted output */
-            va_end(marker);
-            va_start(marker, format);
-            vfprintf(stderr, format, marker);
-          }
-        } else {
-          vfprintf(stderr, format, marker);
-        }
-        va_end(marker);
-      }
-      log_flush();
     }
   }
+  if (log_flags & LOG_FLUSH) {
+    log_flush();
+  }
 }
 
-static unsigned int logfile_level = 0;
+void _log_info(const char *format, ...)
-static unsigned int stderr_level = 1;
-
-void _log_info(unsigned int level, const char *format, ...)
 {
-  va_list marker;
+  const char * prefix = "INFO";
-  fflush(stdout);
+  const int mask = LOG_CPINFO;
-  if (!logfile)
-    logfile = stderr;
-  if (logfile_level >= level) {
-    fprintf(logfile, "INFO[%u]: ", level);
-    va_start(marker, format);
-    vfprintf(logfile, format, marker);
-    va_end(marker);
-    if (logfile != stderr) {
-      if (stderr_level >= level) {
-        fprintf(stderr, "INFO[%u]: ", level);
-        va_start(marker, format);
-        if (stdio_codepage) {
-          char buffer[MAXLENGTH];
-          char converted[MAXLENGTH];
 
-          vsnprintf(buffer, sizeof(buffer), format, marker);
+  /* write to the logfile, always */
-          if (cp_convert(buffer, converted, MAXLENGTH, stdio_codepage) == 0) {
+  if (logfile && (log_flags & mask)) {
-            fputs(converted, stderr);
+    va_list args;
-          } else {
+    va_start(args, format);
-            /* fall back to non-converted output */
+    _log_write(logfile, 0, prefix, format, args);
-            va_end(marker);
+    va_end(args);
-            va_start(marker, format);
+  }
-            vfprintf(stderr, format, marker);
+
-          }
+  /* write to stderr, if that's not the logfile already */
-        } else {
+  if (logfile!=stderr && (log_stderr & mask)) {
-          vfprintf(stderr, format, marker);
+    int dupe = check_dupe(format, prefix);
-        }
+    if (!dupe) {
-        va_end(marker);
+      va_list args;
-      }
+      va_start(args, format);
-      if (log_flags & LOG_FLUSH) {
+      _log_write(stderr, stdio_codepage, prefix, format, args);
-        log_flush();
+      va_end(args);
-      }
     }
   }
+  if (log_flags & LOG_FLUSH) {
+    log_flush();
+  }
 }
+
+void log_printf(FILE * io, const char *format, ...)
+{
+  const char * prefix = "INFO";
+  const int mask = LOG_CPINFO;
+
+  /* write to the logfile, always */
+  if (logfile && (log_flags & mask)) {
+    int codepage = (logfile==stderr || logfile==stdout) ? stdio_codepage : 0;
+    va_list args;
+    va_start(args, format);
+    _log_write(logfile, codepage, prefix, format, args);
+    va_end(args);
+  }
+
+  /* write to io, if that's not the logfile already */
+  if (logfile!=io && (log_stderr & mask)) {
+    int dupe = check_dupe(format, prefix);
+    if (!dupe) {
+      va_list args;
+      va_start(args, format);
+      _log_write(io, stdio_codepage, prefix, format, args);
+      va_end(args);
+    }
+  }
+  if (log_flags & LOG_FLUSH) {
+    log_flush();
+  }
+}
+

src/util/log.h

@@ -16,22 +16,19 @@ extern "C" {
 #endif
 
   extern void log_open(const char *filename);
-  extern void log_printf(const char *str, ...);
-  extern void log_puts(const char *str);
   extern void log_close(void);
   extern void log_flush(void);
-  extern void log_stdio(FILE * io, const char *format, ...);
 
 #define log_warning(x) _log_warn x
 #define log_error(x) _log_error x
-#define log_info(x) _log_info x
 #define log_debug _log_debug
 
   /* use macros above instead of these: */
   extern void _log_warn(const char *format, ...);
   extern void _log_error(const char *format, ...);
   extern void _log_debug(const char *format, ...);
-  extern void _log_info(unsigned int flag, const char *format, ...);
+  extern void log_info(const char *format, ...);
+  extern void log_printf(FILE * ios, const char *format, ...);
 
 #define LOG_FLUSH      0x01
 #define LOG_CPWARNING  0x02
@@ -40,6 +37,7 @@ extern "C" {
 #define LOG_CPINFO     0x10
 
   extern int log_flags;
+  extern int log_stderr;
 #ifdef __cplusplus
 }
 #endif

src/util/umlaut.c

@@ -203,12 +203,13 @@ void freetokens(struct tnode *root)
   }
 }
 
-int findtoken(const tnode * tk, const char *str, variant * result)
+int findtoken(const tnode * tk, const char *key, variant * result)
 {
+  const char * str = key;
   assert(tk);
-  if (!str || *str == 0)
+  if (!str || *str == 0) {
     return E_TOK_NOMATCH;
-
+  }
   do {
     int index;
     const tref *ref;
@@ -218,6 +219,7 @@ int findtoken(const tnode * tk, const char *str, variant * result)
 
     if (ret != 0) {
       /* encoding is broken. youch */
+      log_debug("findtoken | encoding error in '%s'\n", key);
       return E_TOK_NOMATCH;
     }
 #if NODEHASHSIZE == 8
@@ -229,13 +231,16 @@ int findtoken(const tnode * tk, const char *str, variant * result)
     while (ref && ref->ucs != ucs)
       ref = ref->nexthash;
     str += len;
-    if (!ref)
+    if (!ref) {
+      log_debug("findtoken | token not found '%s'\n", key);
       return E_TOK_NOMATCH;
+    }
     tk = ref->node;
   } while (*str);
   if (tk) {
     *result = tk->id;
     return E_TOK_SUCCESS;
   }
+  log_debug("findtoken | token not found '%s'\n", key);
   return E_TOK_NOMATCH;
 }