From ac1310528a248c99e039e7afaf48724ad1b7f10e Mon Sep 17 00:00:00 2001 From: James Yonan Date: Thu, 31 Mar 2011 23:18:06 +0000 Subject: 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 --- errlevel.h | 6 +-- init.c | 2 +- packet_id.c | 147 ++++++++++++++++++++++++++++++++++++++++++++++++++++-------- packet_id.h | 7 ++- ssl.c | 6 ++- version.m4 | 2 +- 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]) -- cgit v1.2.3