]> git.ipfire.org Git - thirdparty/openvpn.git/commitdiff
Added more packet ID debug info at debug level 3 for debugging
authorJames Yonan <james@openvpn.net>
Thu, 31 Mar 2011 23:18:06 +0000 (23:18 +0000)
committerDavid Sommerseth <dazo@users.sourceforge.net>
Tue, 26 Apr 2011 20:29:11 +0000 (22:29 +0200)
false positive packet replays.

Version 2.1.3q.

git-svn-id: http://svn.openvpn.net/projects/openvpn/branches/BETA21/openvpn@7109 e7ae566f-a301-0410-adde-c780ea21d3b5

errlevel.h
init.c
packet_id.c
packet_id.h
ssl.c
version.m4

index 13a711405688761fb9aa7c34f75be6b9c19e302f..be1ef5e0627f1293380f3a1ef69931ee15ca9ccd 100644 (file)
@@ -83,7 +83,7 @@
 #define D_RESTART            LOGLEV(3, 33, 0)        /* show certain restart messages */
 #define D_PUSH               LOGLEV(3, 34, 0)        /* show push/pull info */
 #define D_IFCONFIG_POOL      LOGLEV(3, 35, 0)        /* show ifconfig pool info */
-#define D_BACKTRACK          LOGLEV(3, 36, 0)        /* show replay backtracks */
+#define D_PID_DEBUG_LOW      LOGLEV(3, 36, 0)        /* show low-freq packet-id debugging info */
 #define D_AUTH               LOGLEV(3, 37, 0)        /* show user/pass auth info */
 #define D_MULTI_LOW          LOGLEV(3, 38, 0)        /* show point-to-multipoint low-freq debug info */
 #define D_PLUGIN             LOGLEV(3, 39, 0)        /* show plugin calls */
 #define D_INIT_MEDIUM        LOGLEV(4, 60, 0)        /* show medium frequency init messages */
 #define D_MTU_INFO           LOGLEV(4, 61, 0)        /* show terse MTU info */
 #define D_SHOW_OCC_HASH      LOGLEV(4, 62, 0)        /* show MD5 hash of option compatibility string */
+#define D_PID_DEBUG_MEDIUM   LOGLEV(4, 63, 0)        /* show medium-freq packet-id debugging info */
 
 #define D_LOG_RW             LOGLEV(5, 0,  0)        /* Print 'R' or 'W' to stdout for read/write */
 
 #define D_FRAG_DEBUG         LOGLEV(7, 70, M_DEBUG)  /* show fragment debugging info */
 #define D_WIN32_IO_LOW       LOGLEV(7, 70, M_DEBUG)  /* low freq win32 I/O debugging info */
 #define D_MTU_DEBUG          LOGLEV(7, 70, M_DEBUG)  /* show MTU debugging info */
-#define D_PID_DEBUG_LOW      LOGLEV(7, 70, M_DEBUG)  /* show low-freq packet-id debugging info */
 #define D_MULTI_DEBUG        LOGLEV(7, 70, M_DEBUG)  /* show medium-freq multi debugging info */
 #define D_MSS                LOGLEV(7, 70, M_DEBUG)  /* show MSS adjustments */
 #define D_COMP_LOW           LOGLEV(7, 70, M_DEBUG)  /* show adaptive compression state changes */
 #define D_TLS_KEYSELECT      LOGLEV(7, 70, M_DEBUG)  /* show information on key selection for data channel */
 #define D_ARGV_PARSE_CMD     LOGLEV(7, 70, M_DEBUG)  /* show parse_line() errors in argv_printf %sc */
 #define D_CRYPTO_DEBUG       LOGLEV(7, 70, M_DEBUG)  /* show detailed info from crypto.c routines */
+#define D_PID_DEBUG          LOGLEV(7, 70, M_DEBUG)  /* show packet-id debugging info */
 #define D_PF_DROPPED_BCAST   LOGLEV(7, 71, M_DEBUG)  /* packet filter dropped a broadcast packet */
 #define D_PF_DEBUG           LOGLEV(7, 72, M_DEBUG)  /* packet filter debugging, must also define PF_DEBUG in pf.h */
 
 #define D_READ_WRITE         LOGLEV(9, 70, M_DEBUG)  /* show all tun/tcp/udp reads/writes/opens */
 #define D_PACKET_CONTENT     LOGLEV(9, 70, M_DEBUG)  /* show before/after encryption packet content */
 #define D_TLS_NO_SEND_KEY    LOGLEV(9, 70, M_DEBUG)  /* show when no data channel send-key exists */
-#define D_PID_DEBUG          LOGLEV(9, 70, M_DEBUG)  /* show packet-id debugging info */
 #define D_PID_PERSIST_DEBUG  LOGLEV(9, 70, M_DEBUG)  /* show packet-id persist debugging info */
 #define D_LINK_RW_VERBOSE    LOGLEV(9, 70, M_DEBUG)  /* show link reads/writes with greater verbosity */
 #define D_STREAM_DEBUG       LOGLEV(9, 70, M_DEBUG)  /* show TCP stream debug info */
diff --git a/init.c b/init.c
index 7738f0083e6cf402a8b7e71cc3fbad199d2654f1..a1a1a8fe3ae4e26f8b6260a56ad8a645f257ad16 100644 (file)
--- a/init.c
+++ b/init.c
@@ -1833,7 +1833,7 @@ do_init_crypto_static (struct context *c, const unsigned int flags)
   if (options->replay)
     {
       packet_id_init (&c->c2.packet_id, options->replay_window,
-                     options->replay_time);
+                     options->replay_time, "STATIC", 0);
       c->c2.crypto_options.packet_id = &c->c2.packet_id;
       c->c2.crypto_options.pid_persist = &c->c1.pid_persist;
       c->c2.crypto_options.flags |= CO_PACKET_ID_LONG_FORM;
index b11e71fabe10146158c1c349c166090c90a0bd6b..f38c1212703092c500b76a8cc2ffafed98ac5ce5 100644 (file)
@@ -41,6 +41,8 @@
 
 #include "memdbg.h"
 
+/* #define PID_SIMULATE_BACKTRACK */
+
 /*
  * Special time_t value that indicates that
  * sequence number has expired.
 #define SEQ_UNSEEN  ((time_t)0)
 #define SEQ_EXPIRED ((time_t)1)
 
+static void packet_id_debug_print (int msglevel,
+                                  const struct packet_id_rec *p,
+                                  const struct packet_id_net *pin,
+                                  const char *message,
+                                  int value);
+
+static inline void
+packet_id_debug (int msglevel,
+                const struct packet_id_rec *p,
+                const struct packet_id_net *pin,
+                const char *message,
+                int value)
+{
+#ifdef ENABLE_DEBUG
+  if (unlikely(check_debug_level(msglevel)))
+    packet_id_debug_print (msglevel, p, pin, message, value);
+#endif
+}
+
 void
-packet_id_init (struct packet_id *p, int seq_backtrack, int time_backtrack)
+packet_id_init (struct packet_id *p, int seq_backtrack, int time_backtrack, const char *name, int unit)
 {
-  dmsg (D_PID_DEBUG_LOW, "PID packet_id_init seq_backtrack=%d time_backtrack=%d",
-       seq_backtrack,
-       time_backtrack);
+  dmsg (D_PID_DEBUG, "PID packet_id_init seq_backtrack=%d time_backtrack=%d",
+       seq_backtrack,
+       time_backtrack);
 
   ASSERT (p);
   CLEAR (*p);
 
+  p->rec.name = name;
+  p->rec.unit = unit;
   if (seq_backtrack)
     {
       ASSERT (MIN_SEQ_BACKTRACK <= seq_backtrack && seq_backtrack <= MAX_SEQ_BACKTRACK);
@@ -74,7 +97,7 @@ packet_id_free (struct packet_id *p)
 {
   if (p)
     {
-      dmsg (D_PID_DEBUG_LOW, "PID packet_id_free");
+      dmsg (D_PID_DEBUG, "PID packet_id_free");
       if (p->rec.seq_list)
        free (p->rec.seq_list);
       CLEAR (*p);
@@ -105,7 +128,11 @@ packet_id_add (struct packet_id_rec *p, const struct packet_id_net *pin)
          CIRC_LIST_RESET (p->seq_list);
        }
 
-      while (p->id < pin->id)
+      while (p->id < pin->id
+#ifdef PID_SIMULATE_BACKTRACK
+            || (get_random() % 64) < 31
+#endif
+            )
        {
          CIRC_LIST_PUSH (p->seq_list, SEQ_UNSEEN);
          ++p->id;
@@ -155,17 +182,13 @@ packet_id_reap (struct packet_id_rec *p)
  * it is a replay.
  */
 bool
-packet_id_test (const struct packet_id_rec *p,
+packet_id_test (struct packet_id_rec *p,
                const struct packet_id_net *pin)
 {
-  static int max_backtrack_stat;
   packet_id_type diff;
 
-  dmsg (D_PID_DEBUG,
-       "PID TEST " time_format ":" packet_id_format " " time_format ":" packet_id_format "",
-       (time_type)p->time, (packet_id_print_type)p->id, (time_type)pin->time,
-       (packet_id_print_type)pin->id);
-
+  packet_id_debug (D_PID_DEBUG, p, pin, "PID_TEST", 0);
+  
   ASSERT (p->initialized);
 
   if (!pin->id)
@@ -189,19 +212,35 @@ packet_id_test (const struct packet_id_rec *p,
          diff = p->id - pin->id;
 
          /* keep track of maximum backtrack seen for debugging purposes */
-         if ((int)diff > max_backtrack_stat)
+         if ((int)diff > p->max_backtrack_stat)
            {
-             max_backtrack_stat = (int)diff;
-             msg (D_BACKTRACK, "Replay-window backtrack occurred [%d]", max_backtrack_stat);
+             p->max_backtrack_stat = (int)diff;
+             packet_id_debug (D_PID_DEBUG_LOW, p, pin, "PID_ERR replay-window backtrack occurred", p->max_backtrack_stat);
            }
 
          if (diff >= (packet_id_type) CIRC_LIST_SIZE (p->seq_list))
-           return false;
+           {
+             packet_id_debug (D_PID_DEBUG_LOW, p, pin, "PID_ERR large diff", diff);
+             return false;
+           }
 
-         return CIRC_LIST_ITEM (p->seq_list, diff) == 0;
+         {
+           const time_t v = CIRC_LIST_ITEM (p->seq_list, diff);
+           if (v == 0)
+             return true;
+           else
+             {
+               /* might want to increase this to D_PID_DEBUG_MEDIUM (or even D_PID_DEBUG) in the future */
+               packet_id_debug (D_PID_DEBUG_LOW, p, pin, "PID_ERR replay", diff);
+               return false;
+             }
+         }
        }
       else if (pin->time < p->time) /* if time goes back, reject */
-       return false;
+       {
+         packet_id_debug (D_PID_DEBUG_LOW, p, pin, "PID_ERR time backtrack", 0);
+         return false;
+       }
       else                          /* time moved forward */
        return true;
     }
@@ -434,6 +473,76 @@ packet_id_persist_print (const struct packet_id_persist *p, struct gc_arena *gc)
   return (char *)out.data;
 }
 
+#ifdef ENABLE_DEBUG
+
+static void
+packet_id_debug_print (int msglevel,
+                      const struct packet_id_rec *p,
+                      const struct packet_id_net *pin,
+                      const char *message,
+                      int value)
+{
+  struct gc_arena gc = gc_new ();
+  struct buffer out = alloc_buf_gc (256, &gc);
+  struct timeval tv;
+  const time_t prev_now = now;
+  const struct seq_list *sl = p->seq_list;
+  int i;
+
+  CLEAR (tv);
+  gettimeofday (&tv, NULL);
+
+  buf_printf (&out, "%s [%d]", message, value);
+  buf_printf (&out, " [%s-%d] [", p->name, p->unit);
+  for (i = 0; i < sl->x_size; ++i)
+    {
+      char c;
+      time_t v;
+      int diff;
+
+      v = CIRC_LIST_ITEM(sl, i);
+      if (v == SEQ_UNSEEN)
+       c = '_';
+      else if (v == SEQ_EXPIRED)
+       c = 'E';
+      else
+       {
+         diff = (int) prev_now - v;
+         if (diff < 0)
+           c = 'N';
+         else if (diff < 10)
+           c = '0' + diff;
+         else
+           c = '>';
+       }
+      buf_printf(&out, "%c", c);
+    }
+  buf_printf (&out, "] " time_format ":" packet_id_format, (time_type)p->time, (packet_id_print_type)p->id); 
+  if (pin)
+    buf_printf (&out, " " time_format ":" packet_id_format, (time_type)pin->time, (packet_id_print_type)pin->id);
+
+  buf_printf (&out, " t=" time_format "[%d]",
+             (time_type)prev_now,
+             (int)(prev_now - tv.tv_sec));
+
+  buf_printf (&out, " r=[%d,%d,%d,%d,%d]",
+             (int)(p->last_reap - tv.tv_sec),
+             p->seq_backtrack,
+             p->time_backtrack,
+             p->max_backtrack_stat,
+             (int)p->initialized);
+  buf_printf (&out, " sl=[%d,%d,%d,%d]",
+             sl->x_head,
+             sl->x_size,
+             sl->x_cap,
+             sl->x_sizeof);
+
+  msg (msglevel, "%s", BSTR(&out));
+  gc_free (&gc);
+}
+
+#endif
+
 #ifdef PID_TEST
 
 void
index 12c1df30e25acfb1606c1d1222c819873efa3596..1c341f79bdff6051bd493476caf823ccd3e554d8 100644 (file)
@@ -138,8 +138,11 @@ struct packet_id_rec
   packet_id_type id;          /* highest sequence number received */
   int seq_backtrack;          /* set from --replay-window */
   int time_backtrack;         /* set from --replay-window */
+  int max_backtrack_stat;     /* maximum backtrack seen so far */
   bool initialized;           /* true if packet_id_init was called */
   struct seq_list *seq_list;  /* packet-id "memory" */
+  const char *name;
+  int unit;
 };
 
 /*
@@ -207,11 +210,11 @@ struct packet_id
   struct packet_id_rec rec;
 };
 
-void packet_id_init (struct packet_id *p, int seq_backtrack, int time_backtrack);
+void packet_id_init (struct packet_id *p, int seq_backtrack, int time_backtrack, const char *name, int unit);
 void packet_id_free (struct packet_id *p);
 
 /* should we accept an incoming packet id ? */
-bool packet_id_test (const struct packet_id_rec *p,
+bool packet_id_test (struct packet_id_rec *p,
                     const struct packet_id_net *pin);
 
 /* change our current state to reflect an accepted packet id */
diff --git a/ssl.c b/ssl.c
index d5fe5ba0b452a910617d5aef3fe0feb5f7b6970e..bbb9701c3e0fb2908b3702aa9199280bf0d0137d 100644 (file)
--- a/ssl.c
+++ b/ssl.c
@@ -2644,7 +2644,8 @@ key_state_init (struct tls_session *session, struct key_state *ks)
   /* init packet ID tracker */
   packet_id_init (&ks->packet_id,
                  session->opt->replay_window,
-                 session->opt->replay_time);
+                 session->opt->replay_time,
+                 "SSL", ks->key_id);
 
 #ifdef MANAGEMENT_DEF_AUTH
   ks->mda_key_id = session->opt->mda_context->mda_key_id_counter++;
@@ -2749,7 +2750,8 @@ tls_session_init (struct tls_multi *multi, struct tls_session *session)
   /* initialize packet ID replay window for --tls-auth */
   packet_id_init (session->tls_auth.packet_id,
                  session->opt->replay_window,
-                 session->opt->replay_time);
+                 session->opt->replay_time,
+                 "TLS_AUTH", session->key_id);
 
   /* load most recent packet-id to replay protect on --tls-auth */
   packet_id_persist_load_obj (session->tls_auth.pid_persist, session->tls_auth.packet_id);
index f8b3b8da15f8a4ae34146aa5c2cf7b53a16bc7ae..b539d1aed4600a71e5534711bf646aff65962c19 100644 (file)
@@ -1,5 +1,5 @@
 dnl define the OpenVPN version
-define(PRODUCT_VERSION,[2.1.3p])
+define(PRODUCT_VERSION,[2.1.3q])
 dnl define the TAP version
 define(PRODUCT_TAP_ID,[tap0901])
 define(PRODUCT_TAP_WIN32_MIN_MAJOR,[9])