Browse code

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

James Yonan authored on 2011/04/01 08:18:06
Showing 6 changed files
... ...
@@ -83,7 +83,7 @@
83 83
 #define D_RESTART            LOGLEV(3, 33, 0)        /* show certain restart messages */
84 84
 #define D_PUSH               LOGLEV(3, 34, 0)        /* show push/pull info */
85 85
 #define D_IFCONFIG_POOL      LOGLEV(3, 35, 0)        /* show ifconfig pool info */
86
-#define D_BACKTRACK          LOGLEV(3, 36, 0)        /* show replay backtracks */
86
+#define D_PID_DEBUG_LOW      LOGLEV(3, 36, 0)        /* show low-freq packet-id debugging info */
87 87
 #define D_AUTH               LOGLEV(3, 37, 0)        /* show user/pass auth info */
88 88
 #define D_MULTI_LOW          LOGLEV(3, 38, 0)        /* show point-to-multipoint low-freq debug info */
89 89
 #define D_PLUGIN             LOGLEV(3, 39, 0)        /* show plugin calls */
... ...
@@ -107,6 +107,7 @@
107 107
 #define D_INIT_MEDIUM        LOGLEV(4, 60, 0)        /* show medium frequency init messages */
108 108
 #define D_MTU_INFO           LOGLEV(4, 61, 0)        /* show terse MTU info */
109 109
 #define D_SHOW_OCC_HASH      LOGLEV(4, 62, 0)        /* show MD5 hash of option compatibility string */
110
+#define D_PID_DEBUG_MEDIUM   LOGLEV(4, 63, 0)        /* show medium-freq packet-id debugging info */
110 111
 
111 112
 #define D_LOG_RW             LOGLEV(5, 0,  0)        /* Print 'R' or 'W' to stdout for read/write */
112 113
 
... ...
@@ -121,7 +122,6 @@
121 121
 #define D_FRAG_DEBUG         LOGLEV(7, 70, M_DEBUG)  /* show fragment debugging info */
122 122
 #define D_WIN32_IO_LOW       LOGLEV(7, 70, M_DEBUG)  /* low freq win32 I/O debugging info */
123 123
 #define D_MTU_DEBUG          LOGLEV(7, 70, M_DEBUG)  /* show MTU debugging info */
124
-#define D_PID_DEBUG_LOW      LOGLEV(7, 70, M_DEBUG)  /* show low-freq packet-id debugging info */
125 124
 #define D_MULTI_DEBUG        LOGLEV(7, 70, M_DEBUG)  /* show medium-freq multi debugging info */
126 125
 #define D_MSS                LOGLEV(7, 70, M_DEBUG)  /* show MSS adjustments */
127 126
 #define D_COMP_LOW           LOGLEV(7, 70, M_DEBUG)  /* show adaptive compression state changes */
... ...
@@ -145,6 +145,7 @@
145 145
 #define D_TLS_KEYSELECT      LOGLEV(7, 70, M_DEBUG)  /* show information on key selection for data channel */
146 146
 #define D_ARGV_PARSE_CMD     LOGLEV(7, 70, M_DEBUG)  /* show parse_line() errors in argv_printf %sc */
147 147
 #define D_CRYPTO_DEBUG       LOGLEV(7, 70, M_DEBUG)  /* show detailed info from crypto.c routines */
148
+#define D_PID_DEBUG          LOGLEV(7, 70, M_DEBUG)  /* show packet-id debugging info */
148 149
 #define D_PF_DROPPED_BCAST   LOGLEV(7, 71, M_DEBUG)  /* packet filter dropped a broadcast packet */
149 150
 #define D_PF_DEBUG           LOGLEV(7, 72, M_DEBUG)  /* packet filter debugging, must also define PF_DEBUG in pf.h */
150 151
 
... ...
@@ -162,7 +163,6 @@
162 162
 #define D_READ_WRITE         LOGLEV(9, 70, M_DEBUG)  /* show all tun/tcp/udp reads/writes/opens */
163 163
 #define D_PACKET_CONTENT     LOGLEV(9, 70, M_DEBUG)  /* show before/after encryption packet content */
164 164
 #define D_TLS_NO_SEND_KEY    LOGLEV(9, 70, M_DEBUG)  /* show when no data channel send-key exists */
165
-#define D_PID_DEBUG          LOGLEV(9, 70, M_DEBUG)  /* show packet-id debugging info */
166 165
 #define D_PID_PERSIST_DEBUG  LOGLEV(9, 70, M_DEBUG)  /* show packet-id persist debugging info */
167 166
 #define D_LINK_RW_VERBOSE    LOGLEV(9, 70, M_DEBUG)  /* show link reads/writes with greater verbosity */
168 167
 #define D_STREAM_DEBUG       LOGLEV(9, 70, M_DEBUG)  /* show TCP stream debug info */
... ...
@@ -1833,7 +1833,7 @@ do_init_crypto_static (struct context *c, const unsigned int flags)
1833 1833
   if (options->replay)
1834 1834
     {
1835 1835
       packet_id_init (&c->c2.packet_id, options->replay_window,
1836
-		      options->replay_time);
1836
+		      options->replay_time, "STATIC", 0);
1837 1837
       c->c2.crypto_options.packet_id = &c->c2.packet_id;
1838 1838
       c->c2.crypto_options.pid_persist = &c->c1.pid_persist;
1839 1839
       c->c2.crypto_options.flags |= CO_PACKET_ID_LONG_FORM;
... ...
@@ -41,6 +41,8 @@
41 41
 
42 42
 #include "memdbg.h"
43 43
 
44
+/* #define PID_SIMULATE_BACKTRACK */
45
+
44 46
 /*
45 47
  * Special time_t value that indicates that
46 48
  * sequence number has expired.
... ...
@@ -48,16 +50,37 @@
48 48
 #define SEQ_UNSEEN  ((time_t)0)
49 49
 #define SEQ_EXPIRED ((time_t)1)
50 50
 
51
+static void packet_id_debug_print (int msglevel,
52
+				   const struct packet_id_rec *p,
53
+				   const struct packet_id_net *pin,
54
+				   const char *message,
55
+				   int value);
56
+
57
+static inline void
58
+packet_id_debug (int msglevel,
59
+		 const struct packet_id_rec *p,
60
+		 const struct packet_id_net *pin,
61
+		 const char *message,
62
+		 int value)
63
+{
64
+#ifdef ENABLE_DEBUG
65
+  if (unlikely(check_debug_level(msglevel)))
66
+    packet_id_debug_print (msglevel, p, pin, message, value);
67
+#endif
68
+}
69
+
51 70
 void
52
-packet_id_init (struct packet_id *p, int seq_backtrack, int time_backtrack)
71
+packet_id_init (struct packet_id *p, int seq_backtrack, int time_backtrack, const char *name, int unit)
53 72
 {
54
-  dmsg (D_PID_DEBUG_LOW, "PID packet_id_init seq_backtrack=%d time_backtrack=%d",
55
-       seq_backtrack,
56
-       time_backtrack);
73
+  dmsg (D_PID_DEBUG, "PID packet_id_init seq_backtrack=%d time_backtrack=%d",
74
+	seq_backtrack,
75
+	time_backtrack);
57 76
 
58 77
   ASSERT (p);
59 78
   CLEAR (*p);
60 79
 
80
+  p->rec.name = name;
81
+  p->rec.unit = unit;
61 82
   if (seq_backtrack)
62 83
     {
63 84
       ASSERT (MIN_SEQ_BACKTRACK <= seq_backtrack && seq_backtrack <= MAX_SEQ_BACKTRACK);
... ...
@@ -74,7 +97,7 @@ packet_id_free (struct packet_id *p)
74 74
 {
75 75
   if (p)
76 76
     {
77
-      dmsg (D_PID_DEBUG_LOW, "PID packet_id_free");
77
+      dmsg (D_PID_DEBUG, "PID packet_id_free");
78 78
       if (p->rec.seq_list)
79 79
 	free (p->rec.seq_list);
80 80
       CLEAR (*p);
... ...
@@ -105,7 +128,11 @@ packet_id_add (struct packet_id_rec *p, const struct packet_id_net *pin)
105 105
 	  CIRC_LIST_RESET (p->seq_list);
106 106
 	}
107 107
 
108
-      while (p->id < pin->id)
108
+      while (p->id < pin->id
109
+#ifdef PID_SIMULATE_BACKTRACK
110
+	     || (get_random() % 64) < 31
111
+#endif
112
+	     )
109 113
 	{
110 114
 	  CIRC_LIST_PUSH (p->seq_list, SEQ_UNSEEN);
111 115
 	  ++p->id;
... ...
@@ -155,17 +182,13 @@ packet_id_reap (struct packet_id_rec *p)
155 155
  * it is a replay.
156 156
  */
157 157
 bool
158
-packet_id_test (const struct packet_id_rec *p,
158
+packet_id_test (struct packet_id_rec *p,
159 159
 		const struct packet_id_net *pin)
160 160
 {
161
-  static int max_backtrack_stat;
162 161
   packet_id_type diff;
163 162
 
164
-  dmsg (D_PID_DEBUG,
165
-       "PID TEST " time_format ":" packet_id_format " " time_format ":" packet_id_format "",
166
-       (time_type)p->time, (packet_id_print_type)p->id, (time_type)pin->time,
167
-       (packet_id_print_type)pin->id);
168
-
163
+  packet_id_debug (D_PID_DEBUG, p, pin, "PID_TEST", 0);
164
+  
169 165
   ASSERT (p->initialized);
170 166
 
171 167
   if (!pin->id)
... ...
@@ -189,19 +212,35 @@ packet_id_test (const struct packet_id_rec *p,
189 189
 	  diff = p->id - pin->id;
190 190
 
191 191
 	  /* keep track of maximum backtrack seen for debugging purposes */
192
-	  if ((int)diff > max_backtrack_stat)
192
+	  if ((int)diff > p->max_backtrack_stat)
193 193
 	    {
194
-	      max_backtrack_stat = (int)diff;
195
-	      msg (D_BACKTRACK, "Replay-window backtrack occurred [%d]", max_backtrack_stat);
194
+	      p->max_backtrack_stat = (int)diff;
195
+	      packet_id_debug (D_PID_DEBUG_LOW, p, pin, "PID_ERR replay-window backtrack occurred", p->max_backtrack_stat);
196 196
 	    }
197 197
 
198 198
 	  if (diff >= (packet_id_type) CIRC_LIST_SIZE (p->seq_list))
199
-	    return false;
199
+	    {
200
+	      packet_id_debug (D_PID_DEBUG_LOW, p, pin, "PID_ERR large diff", diff);
201
+	      return false;
202
+	    }
200 203
 
201
-	  return CIRC_LIST_ITEM (p->seq_list, diff) == 0;
204
+	  {
205
+	    const time_t v = CIRC_LIST_ITEM (p->seq_list, diff);
206
+	    if (v == 0)
207
+	      return true;
208
+	    else
209
+	      {
210
+		/* might want to increase this to D_PID_DEBUG_MEDIUM (or even D_PID_DEBUG) in the future */
211
+		packet_id_debug (D_PID_DEBUG_LOW, p, pin, "PID_ERR replay", diff);
212
+		return false;
213
+	      }
214
+	  }
202 215
 	}
203 216
       else if (pin->time < p->time) /* if time goes back, reject */
204
-	return false;
217
+	{
218
+	  packet_id_debug (D_PID_DEBUG_LOW, p, pin, "PID_ERR time backtrack", 0);
219
+	  return false;
220
+	}
205 221
       else                          /* time moved forward */
206 222
 	return true;
207 223
     }
... ...
@@ -434,6 +473,76 @@ packet_id_persist_print (const struct packet_id_persist *p, struct gc_arena *gc)
434 434
   return (char *)out.data;
435 435
 }
436 436
 
437
+#ifdef ENABLE_DEBUG
438
+
439
+static void
440
+packet_id_debug_print (int msglevel,
441
+		       const struct packet_id_rec *p,
442
+		       const struct packet_id_net *pin,
443
+		       const char *message,
444
+		       int value)
445
+{
446
+  struct gc_arena gc = gc_new ();
447
+  struct buffer out = alloc_buf_gc (256, &gc);
448
+  struct timeval tv;
449
+  const time_t prev_now = now;
450
+  const struct seq_list *sl = p->seq_list;
451
+  int i;
452
+
453
+  CLEAR (tv);
454
+  gettimeofday (&tv, NULL);
455
+
456
+  buf_printf (&out, "%s [%d]", message, value);
457
+  buf_printf (&out, " [%s-%d] [", p->name, p->unit);
458
+  for (i = 0; i < sl->x_size; ++i)
459
+    {
460
+      char c;
461
+      time_t v;
462
+      int diff;
463
+
464
+      v = CIRC_LIST_ITEM(sl, i);
465
+      if (v == SEQ_UNSEEN)
466
+	c = '_';
467
+      else if (v == SEQ_EXPIRED)
468
+	c = 'E';
469
+      else
470
+	{
471
+	  diff = (int) prev_now - v;
472
+	  if (diff < 0)
473
+	    c = 'N';
474
+	  else if (diff < 10)
475
+	    c = '0' + diff;
476
+	  else
477
+	    c = '>';
478
+	}
479
+      buf_printf(&out, "%c", c);
480
+    }
481
+  buf_printf (&out, "] " time_format ":" packet_id_format, (time_type)p->time, (packet_id_print_type)p->id); 
482
+  if (pin)
483
+    buf_printf (&out, " " time_format ":" packet_id_format, (time_type)pin->time, (packet_id_print_type)pin->id);
484
+
485
+  buf_printf (&out, " t=" time_format "[%d]",
486
+	      (time_type)prev_now,
487
+	      (int)(prev_now - tv.tv_sec));
488
+
489
+  buf_printf (&out, " r=[%d,%d,%d,%d,%d]",
490
+	      (int)(p->last_reap - tv.tv_sec),
491
+	      p->seq_backtrack,
492
+	      p->time_backtrack,
493
+	      p->max_backtrack_stat,
494
+	      (int)p->initialized);
495
+  buf_printf (&out, " sl=[%d,%d,%d,%d]",
496
+	      sl->x_head,
497
+	      sl->x_size,
498
+	      sl->x_cap,
499
+	      sl->x_sizeof);
500
+
501
+  msg (msglevel, "%s", BSTR(&out));
502
+  gc_free (&gc);
503
+}
504
+
505
+#endif
506
+
437 507
 #ifdef PID_TEST
438 508
 
439 509
 void
... ...
@@ -138,8 +138,11 @@ struct packet_id_rec
138 138
   packet_id_type id;          /* highest sequence number received */
139 139
   int seq_backtrack;          /* set from --replay-window */
140 140
   int time_backtrack;         /* set from --replay-window */
141
+  int max_backtrack_stat;     /* maximum backtrack seen so far */
141 142
   bool initialized;           /* true if packet_id_init was called */
142 143
   struct seq_list *seq_list;  /* packet-id "memory" */
144
+  const char *name;
145
+  int unit;
143 146
 };
144 147
 
145 148
 /*
... ...
@@ -207,11 +210,11 @@ struct packet_id
207 207
   struct packet_id_rec rec;
208 208
 };
209 209
 
210
-void packet_id_init (struct packet_id *p, int seq_backtrack, int time_backtrack);
210
+void packet_id_init (struct packet_id *p, int seq_backtrack, int time_backtrack, const char *name, int unit);
211 211
 void packet_id_free (struct packet_id *p);
212 212
 
213 213
 /* should we accept an incoming packet id ? */
214
-bool packet_id_test (const struct packet_id_rec *p,
214
+bool packet_id_test (struct packet_id_rec *p,
215 215
 		     const struct packet_id_net *pin);
216 216
 
217 217
 /* change our current state to reflect an accepted packet id */
... ...
@@ -2644,7 +2644,8 @@ key_state_init (struct tls_session *session, struct key_state *ks)
2644 2644
   /* init packet ID tracker */
2645 2645
   packet_id_init (&ks->packet_id,
2646 2646
 		  session->opt->replay_window,
2647
-		  session->opt->replay_time);
2647
+		  session->opt->replay_time,
2648
+		  "SSL", ks->key_id);
2648 2649
 
2649 2650
 #ifdef MANAGEMENT_DEF_AUTH
2650 2651
   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)
2749 2749
   /* initialize packet ID replay window for --tls-auth */
2750 2750
   packet_id_init (session->tls_auth.packet_id,
2751 2751
 		  session->opt->replay_window,
2752
-		  session->opt->replay_time);
2752
+		  session->opt->replay_time,
2753
+		  "TLS_AUTH", session->key_id);
2753 2754
 
2754 2755
   /* load most recent packet-id to replay protect on --tls-auth */
2755 2756
   packet_id_persist_load_obj (session->tls_auth.pid_persist, session->tls_auth.packet_id);
... ...
@@ -1,5 +1,5 @@
1 1
 dnl define the OpenVPN version
2
-define(PRODUCT_VERSION,[2.1.3p])
2
+define(PRODUCT_VERSION,[2.1.3q])
3 3
 dnl define the TAP version
4 4
 define(PRODUCT_TAP_ID,[tap0901])
5 5
 define(PRODUCT_TAP_WIN32_MIN_MAJOR,[9])