EXPERIMENTAL WORKAROUND: START OF MODE QUEUE DEQUEUING DELAYED + merg…

…e of eggheads#1441 and eggheads#1087 for better logging during debug session

eggdrop.conf

@@ -187,8 +187,9 @@ logfile mco * "logs/eggdrop.log"
 set log-time 1
 
 # Set the following to the timestamp for the logfile entries. Popular times
-# might be "[%H:%M]" (hour, min), or "[%H:%M:%S]" (hour, min, sec).
-# Read `man strftime' for more formatting options. Keep it below 32 chars.
+# might be "[%H:%M]" (hour, min), or "[%H:%M:%S]" (hour, min, sec). Read
+# 'man strftime' for more formatting options. Additionally eggdrop supports %f
+# for milliseconds. Keep it below 32 chars.
 set timestamp-format {[%H:%M:%S]}
 
 # If you want to keep your logfiles forever, turn this setting on. All
@@ -1515,7 +1516,7 @@ set xfer-timeout 30
 #loadmodule compress
 
 # Allow compressed sending of user files? The user files are compressed with
-# the compression level defined in `compress-level'.
+# the compression level defined in 'compress-level'.
 set share-compressed 1
 
 # This is the default compression level used. These levels are the same as

src/misc.c

@@ -514,11 +514,13 @@ void putlog (int type, char *chname, const char *format, ...)
 {
   static int inhere = 0;
   int i, tsl = 0;
-  char s[LOGLINELEN], path[PATH_MAX], *out, ct[81], *s2, stamp[34];
+  char s[LOGLINELEN], path[PATH_MAX], *out, ct[81], *s2, stamp[34],
+       stamp2[sizeof stamp], *f, c;
   va_list va;
   time_t now2 = time(NULL);
   static time_t now2_last = 0; /* cache expensive localtime() */
   static struct tm t;
+  struct timeval tv;
 
   if (now2 != now2_last) {
     now2_last = now2;
@@ -529,12 +531,25 @@ void putlog (int type, char *chname, const char *format, ...)
 
   /* Create the timestamp */
   if (shtime) {
-    strftime(stamp, sizeof(stamp) - 2, log_ts, &t);
-    strcat(stamp, " ");
-    tsl = strlen(stamp);
+    strlcpy(stamp, log_ts, sizeof stamp);
+
+    /* handle millisecond specifier %f */
+    if ((f = strstr(stamp, "%f")) && ((f - 1) != (strstr(stamp, "%%f")))) {
+      memmove(f + 3, f + 2, strlen(f + 2) + 1);
+      c = f[3]; /* save the char the following snprintf() will overwrite with
+                 * null terminator
+                 */
+      gettimeofday(&tv, NULL);
+      snprintf(f, sizeof stamp - (f - stamp), "%03i", (int) tv.tv_usec / 1000);
+      f[3] = c;
+    }
+
+    strftime(stamp2, sizeof(stamp2) - 2, stamp, &t);
+    strcat(stamp2, " ");
+    tsl = strlen(stamp2);
   }
   else
-    *stamp = '\0';
+    *stamp2 = '\0';
 
   /* Format log entry at offset 'tsl,' then i can prepend the timestamp */
   out = s + tsl;
@@ -566,7 +581,7 @@ void putlog (int type, char *chname, const char *format, ...)
   }
   /* Place the timestamp in the string to be printed */
   if (out[0] && shtime) {
-    memcpy(s, stamp, tsl);
+    memcpy(s, stamp2, tsl);
     out = s;
   }
   strcat(out, "\n");
@@ -599,7 +614,7 @@ void putlog (int type, char *chname, const char *format, ...)
                * then reset repeats. We want the current time here,
                * so put that in the file first.
                */
-              fprintf(logs[i].f, "%s", stamp);
+              fprintf(logs[i].f, "%s", stamp2);
               fprintf(logs[i].f, MISC_LOGREPEAT, logs[i].repeats);
               logs[i].repeats = 0;
               /* No need to reset logs[i].szlast here

src/mod/server.mod/server.c

@@ -206,6 +206,11 @@ static void deq_msg()
 
   /* Send up to 4 msgs to server if the *critical queue* has anything in it */
   if (modeq.head) {
+    if (trying_server) {
+      putlog(LOG_MISC, "*", "EXPERIMENTAL WORKAROUND: START OF MODE QUEUE DEQUEUING DELAYED");
+      return;
+    }
+
     while (modeq.head && (burst < 4) && ((last_time - now) < MAXPENALTY)) {
       if (deq_kick(DP_MODE)) {
         burst++;