Added more packet ID debug info at debug level 3 for debugging

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

6 files changed, 142 insertions, 28 deletions

diff --git a/errlevel.h b/errlevel.h
index 13a7114..be1ef5e 100644
--- a/errlevel.h
+++ b/errlevel.h
@@ -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 */
@@ -107,6 +107,7 @@
 #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 */
 
@@ -121,7 +122,6 @@
 #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 */
@@ -145,6 +145,7 @@
 #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 */
 
@@ -162,7 +163,6 @@
 #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 7738f00..a1a1a8f 100644
--- 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;
diff --git a/packet_id.c b/packet_id.c
index b11e71f..f38c121 100644
--- a/packet_id.c
+++ b/packet_id.c
@@ -41,6 +41,8 @@
 
 #include "memdbg.h"
 
+/* #define PID_SIMULATE_BACKTRACK */
+
 /*
  * Special time_t value that indicates that
  * sequence number has expired.
@@ -48,16 +50,37 @@
 #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
diff --git a/packet_id.h b/packet_id.h
index 12c1df3..1c341f7 100644
--- a/packet_id.h
+++ b/packet_id.h
@@ -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 d5fe5ba..bbb9701 100644
--- 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);
diff --git a/version.m4 b/version.m4
index f8b3b8d..b539d1a 100644
--- a/version.m4
+++ b/version.m4
@@ -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])