Repository: trafficserver Updated Branches: refs/heads/master dffd7f892 -> 6e3ce5022
TS-3534: Wiretracing SSL Connections. This closes #246. Project: http://git-wip-us.apache.org/repos/asf/trafficserver/repo Commit: http://git-wip-us.apache.org/repos/asf/trafficserver/commit/6e3ce502 Tree: http://git-wip-us.apache.org/repos/asf/trafficserver/tree/6e3ce502 Diff: http://git-wip-us.apache.org/repos/asf/trafficserver/diff/6e3ce502 Branch: refs/heads/master Commit: 6e3ce5022d67a9c4098595d3d45e24a3c697c80c Parents: dffd7f8 Author: [email protected] <[email protected]> Authored: Thu Oct 2 12:27:56 2014 -0700 Committer: shinrich <[email protected]> Committed: Fri Jul 10 07:00:32 2015 -0500 ---------------------------------------------------------------------- iocore/net/Makefile.am | 1 + iocore/net/P_SSLConfig.h | 7 ++ iocore/net/P_SSLNetVConnection.h | 11 ++ iocore/net/P_UnixNetVConnection.h | 20 ++++ iocore/net/SSLConfig.cc | 32 +++++- iocore/net/SSLNetVConnection.cc | 191 +++++++++++++++++++++++++++++++-- iocore/net/SSLUtils.cc | 9 +- iocore/net/UnixNetVConnection.cc | 46 +++++++- mgmt/RecordsConfig.cc | 8 ++ proxy/http/HttpSM.cc | 29 ++++- proxy/logging/Log.cc | 49 +++++++++ proxy/logging/Log.h | 15 ++- 12 files changed, 403 insertions(+), 15 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/trafficserver/blob/6e3ce502/iocore/net/Makefile.am ---------------------------------------------------------------------- diff --git a/iocore/net/Makefile.am b/iocore/net/Makefile.am index 81c07ab..7c4b440 100644 --- a/iocore/net/Makefile.am +++ b/iocore/net/Makefile.am @@ -25,6 +25,7 @@ AM_CPPFLAGS = \ -I$(top_srcdir)/proxy \ -I$(top_srcdir)/proxy/hdrs \ -I$(top_srcdir)/proxy/shared \ + -I$(top_srcdir)/proxy/logging \ -I$(top_srcdir)/mgmt \ -I$(top_srcdir)/mgmt/utils \ -I$(top_srcdir)/proxy/api/ts \ http://git-wip-us.apache.org/repos/asf/trafficserver/blob/6e3ce502/iocore/net/P_SSLConfig.h ---------------------------------------------------------------------- diff --git a/iocore/net/P_SSLConfig.h b/iocore/net/P_SSLConfig.h index 1a6cd60..5c582d1 100644 --- a/iocore/net/P_SSLConfig.h +++ b/iocore/net/P_SSLConfig.h @@ -98,6 +98,13 @@ struct SSLConfigParams : public ConfigInfo { static size_t session_cache_max_bucket_size; static bool session_cache_skip_on_lock_contention; + // TS-3435 Wiretracing for SSL Connections + static int ssl_wire_trace_enabled; + static char * ssl_wire_trace_addr; + static IpAddr * ssl_wire_trace_ip; + static int ssl_wire_trace_percentage; + static char * ssl_wire_trace_server_name; + static init_ssl_ctx_func init_ssl_ctx_cb; void initialize(); http://git-wip-us.apache.org/repos/asf/trafficserver/blob/6e3ce502/iocore/net/P_SSLNetVConnection.h ---------------------------------------------------------------------- diff --git a/iocore/net/P_SSLNetVConnection.h b/iocore/net/P_SSLNetVConnection.h index 6a583f5..678035b 100644 --- a/iocore/net/P_SSLNetVConnection.h +++ b/iocore/net/P_SSLNetVConnection.h @@ -253,6 +253,16 @@ public: return eosRcvd; } + bool getSSLTrace() const { + return sslTrace || super::origin_trace; + }; + + void setSSLTrace(bool state){ + sslTrace = state; + }; + + bool computeSSLTrace(); + private: SSLNetVConnection(const SSLNetVConnection &); SSLNetVConnection &operator=(const SSLNetVConnection &); @@ -294,6 +304,7 @@ private: MIOBuffer *iobuf; IOBufferReader *reader; bool eosRcvd; + bool sslTrace; }; typedef int (SSLNetVConnection::*SSLNetVConnHandler)(int, void *); http://git-wip-us.apache.org/repos/asf/trafficserver/blob/6e3ce502/iocore/net/P_UnixNetVConnection.h ---------------------------------------------------------------------- diff --git a/iocore/net/P_UnixNetVConnection.h b/iocore/net/P_UnixNetVConnection.h index e11640b..5b3cd9d 100644 --- a/iocore/net/P_UnixNetVConnection.h +++ b/iocore/net/P_UnixNetVConnection.h @@ -261,6 +261,11 @@ public: ink_hrtime submit_time; OOB_callback *oob_ptr; bool from_accept_thread; + + // es - origin_trace associated connections + bool origin_trace; + const sockaddr *origin_trace_addr; + int origin_trace_port; int startEvent(int event, Event *e); int acceptEvent(int event, Event *e); @@ -277,6 +282,21 @@ public: virtual void apply_options(); friend void write_to_net_io(NetHandler *, UnixNetVConnection *, EThread *); + + void setOriginTrace(bool t) + { + origin_trace = t; + } + + void setOriginTraceAddr(const sockaddr *addr) + { + origin_trace_addr = addr; + } + + void setOriginTracePort(int port) + { + origin_trace_port = port; + } }; extern ClassAllocator<UnixNetVConnection> netVCAllocator; http://git-wip-us.apache.org/repos/asf/trafficserver/blob/6e3ce502/iocore/net/SSLConfig.cc ---------------------------------------------------------------------- diff --git a/iocore/net/SSLConfig.cc b/iocore/net/SSLConfig.cc index 0690655..28a9662 100644 --- a/iocore/net/SSLConfig.cc +++ b/iocore/net/SSLConfig.cc @@ -52,10 +52,16 @@ int SSLConfigParams::ssl_handshake_timeout_in = 0; size_t SSLConfigParams::session_cache_number_buckets = 1024; bool SSLConfigParams::session_cache_skip_on_lock_contention = false; size_t SSLConfigParams::session_cache_max_bucket_size = 100; - init_ssl_ctx_func SSLConfigParams::init_ssl_ctx_cb = NULL; -static ConfigUpdateHandler<SSLCertificateConfig> *sslCertUpdate; +// TS-3534 Wiretracing for SSL Connections +int SSLConfigParams::ssl_wire_trace_enabled = 0; +char *SSLConfigParams::ssl_wire_trace_addr = NULL; +IpAddr * SSLConfigParams::ssl_wire_trace_ip = NULL; +int SSLConfigParams::ssl_wire_trace_percentage = 0; +char *SSLConfigParams::ssl_wire_trace_server_name = NULL; + +static ConfigUpdateHandler<SSLCertificateConfig> * sslCertUpdate; SSLConfigParams::SSLConfigParams() { @@ -97,6 +103,7 @@ SSLConfigParams::cleanup() ats_free_null(cipherSuite); ats_free_null(client_cipherSuite); ats_free_null(dhparamsFile); + ats_free_null(ssl_wire_trace_ip); clientCertLevel = client_verify_depth = verify_depth = clientVerify = 0; } @@ -297,6 +304,27 @@ SSLConfigParams::initialize() ats_free(ssl_client_ca_cert_filename); REC_ReadConfigInt32(ssl_allow_client_renegotiation, "proxy.config.ssl.allow_client_renegotiation"); + + //SSL Wire Trace configurations + REC_ReadConfigInteger(ssl_wire_trace_enabled, "proxy.config.ssl.wire_trace_enabled"); + if(ssl_wire_trace_enabled){ + // wire trace specific source ip + REC_ReadConfigStringAlloc(ssl_wire_trace_addr, "proxy.config.ssl.wire_trace_addr"); + if(ssl_wire_trace_addr){ + ssl_wire_trace_ip = new IpAddr(); + ssl_wire_trace_ip->load(ssl_wire_trace_addr); + } else { + ssl_wire_trace_ip = NULL; + } + // wire trace percentage of requests + REC_ReadConfigInteger(ssl_wire_trace_percentage, "proxy.config.ssl.wire_trace_percentage"); + REC_ReadConfigStringAlloc(ssl_wire_trace_server_name, "proxy.config.ssl.wire_trace_server_name"); + } else { + ssl_wire_trace_addr = NULL; + ssl_wire_trace_ip = NULL; + ssl_wire_trace_percentage = 0; + ssl_wire_trace_server_name = NULL; + } } void http://git-wip-us.apache.org/repos/asf/trafficserver/blob/6e3ce502/iocore/net/SSLNetVConnection.cc ---------------------------------------------------------------------- diff --git a/iocore/net/SSLNetVConnection.cc b/iocore/net/SSLNetVConnection.cc index 153aa19..614d39a 100644 --- a/iocore/net/SSLNetVConnection.cc +++ b/iocore/net/SSLNetVConnection.cc @@ -25,7 +25,12 @@ #include "P_Net.h" #include "P_SSLNextProtocolSet.h" #include "P_SSLUtils.h" -#include "InkAPIInternal.h" // Added to include the ssl_hook definitions +#include "InkAPIInternal.h" // Added to include the ssl_hook definitions +#include "P_SSLConfig.h" +#include "Log.h" + +#include <climits> +#include <string> #if !TS_USE_SET_RBIO // Defined in SSLInternal.c, should probably make a separate include @@ -194,6 +199,9 @@ ssl_read_from_net(SSLNetVConnection *sslvc, EThread *lthread, int64_t &ret) int64_t block_write_avail = 0; ssl_error_t sslErr = SSL_ERROR_NONE; int64_t nread = 0; + + bool trace = sslvc->getSSLTrace(); + Debug("ssl", "trace=%s", trace ? "TRUE" : "FALSE"); for (bytes_read = 0; (b != 0) && (sslErr == SSL_ERROR_NONE); b = b->next) { block_write_avail = b->write_avail(); @@ -206,6 +214,17 @@ ssl_read_from_net(SSLNetVConnection *sslvc, EThread *lthread, int64_t &ret) sslErr = SSLReadBuffer(sslvc->ssl, b->end() + offset, block_write_avail, nread); Debug("ssl", "[SSL_NetVConnection::ssl_read_from_net] nread=%d", (int)nread); + if (!sslvc->origin_trace) { + TraceIn((0 < nread && trace), sslvc->get_remote_addr(), sslvc->get_remote_port(), + "WIRE TRACE\tbytes=%d\n%.*s", (int)nread, (int)nread, b->end() + offset); + } else { + char origin_trace_ip[INET6_ADDRSTRLEN]; + ats_ip_ntop(sslvc->origin_trace_addr, origin_trace_ip, sizeof (origin_trace_ip)); + TraceIn((0 < nread && trace), sslvc->get_remote_addr(), sslvc->get_remote_port(), + "CLIENT %s:%d\ttbytes=%d\n%.*s", origin_trace_ip, sslvc->origin_trace_port, + (int)nread, (int)nread, b->end() + offset); + } + switch (sslErr) { case SSL_ERROR_NONE: @@ -234,30 +253,43 @@ ssl_read_from_net(SSLNetVConnection *sslvc, EThread *lthread, int64_t &ret) Debug("ssl.error", "[SSL_NetVConnection::ssl_read_from_net] SSL_ERROR_WOULD_BLOCK(read)"); break; case SSL_ERROR_WANT_X509_LOOKUP: + TraceIn(trace, sslvc->get_remote_addr(), sslvc->get_remote_port(), + "Want X509 lookup"); event = SSL_READ_WOULD_BLOCK; SSL_INCREMENT_DYN_STAT(ssl_error_want_x509_lookup); Debug("ssl.error", "[SSL_NetVConnection::ssl_read_from_net] SSL_ERROR_WOULD_BLOCK(read/x509 lookup)"); break; case SSL_ERROR_SYSCALL: + TraceIn(trace, sslvc->get_remote_addr(), sslvc->get_remote_port(), + "Syscall Error: %s", strerror(errno)); SSL_INCREMENT_DYN_STAT(ssl_error_syscall); if (nread != 0) { // not EOF event = SSL_READ_ERROR; ret = errno; Debug("ssl.error", "[SSL_NetVConnection::ssl_read_from_net] SSL_ERROR_SYSCALL, underlying IO error: %s", strerror(errno)); + TraceIn(trace, sslvc->get_remote_addr(), sslvc->get_remote_port(), + "Underlying IO error: %d", errno); } else { // then EOF observed, treat it as EOS event = SSL_READ_EOS; - // Error("[SSL_NetVConnection::ssl_read_from_net] SSL_ERROR_SYSCALL, EOF observed violating SSL protocol"); + //Error("[SSL_NetVConnection::ssl_read_from_net] SSL_ERROR_SYSCALL, EOF observed violating SSL protocol"); + TraceIn(trace, sslvc->get_remote_addr(), sslvc->get_remote_port(), + "EOF observed violating SSL protocol"); } break; case SSL_ERROR_ZERO_RETURN: + TraceIn(trace, sslvc->get_remote_addr(), sslvc->get_remote_port(), + "Connection closed by peer"); event = SSL_READ_EOS; SSL_INCREMENT_DYN_STAT(ssl_error_zero_return); Debug("ssl.error", "[SSL_NetVConnection::ssl_read_from_net] SSL_ERROR_ZERO_RETURN"); break; case SSL_ERROR_SSL: default: + TraceIn(trace, sslvc->get_remote_addr(), sslvc->get_remote_port(), + "SSL Error: sslErr=%d, errno=%d", sslErr, + errno); event = SSL_READ_ERROR; ret = errno; SSL_CLR_ERR_INCR_DYN_STAT(sslvc, ssl_error_ssl, "[SSL_NetVConnection::ssl_read_from_net]: errno=%d", errno); @@ -269,6 +301,7 @@ ssl_read_from_net(SSLNetVConnection *sslvc, EThread *lthread, int64_t &ret) if (bytes_read > 0) { Debug("ssl", "[SSL_NetVConnection::ssl_read_from_net] bytes_read=%" PRId64, bytes_read); + buf.writer()->fill(bytes_read); s->vio.ndone += bytes_read; sslvc->netActivity(lthread); @@ -440,6 +473,7 @@ SSLNetVConnection::net_read_io(NetHandler *nh, EThread *lthread) // so it will get forwarded onto the origin server if (!this->getSSLHandShakeComplete()) { this->sslHandShakeComplete = 1; + // Copy over all data already read in during the SSL_accept // (the client hello message) NetState *s = &this->read; @@ -670,7 +704,10 @@ SSLNetVConnection::load_buffer_and_write(int64_t towrite, int64_t &wattempted, i if (HttpProxyPort::TRANSPORT_BLIND_TUNNEL == this->attributes) { return this->super::load_buffer_and_write(towrite, wattempted, total_written, buf, needs); } - + + bool trace = getSSLTrace(); + Debug("ssl", "trace=%s", trace ? "TRUE" : "FALSE"); + do { // check if we have done this block l = b->read_avail(); @@ -716,6 +753,17 @@ SSLNetVConnection::load_buffer_and_write(int64_t towrite, int64_t &wattempted, i towrite, b); err = SSLWriteBuffer(ssl, b->start() + offset, l, r); + if (!origin_trace) { + TraceOut((0 < r && trace), get_remote_addr(), get_remote_port(), + "WIRE TRACE\tbytes=%d\n%.*s", (int)r, (int)r, b->start() + offset); + } else { + char origin_trace_ip[INET6_ADDRSTRLEN]; + ats_ip_ntop(origin_trace_addr, origin_trace_ip, sizeof (origin_trace_ip)); + TraceOut((0 < r && trace), get_remote_addr(), get_remote_port(), + "CLIENT %s:%d\ttbytes=%d\n%.*s", origin_trace_ip, origin_trace_port, + (int)r, (int)r, b->start() + offset); + } + if (r == l) { wattempted = total_written; } @@ -757,29 +805,38 @@ SSLNetVConnection::load_buffer_and_write(int64_t towrite, int64_t &wattempted, i break; case SSL_ERROR_WANT_WRITE: case SSL_ERROR_WANT_X509_LOOKUP: { - if (SSL_ERROR_WANT_WRITE == err) + if (SSL_ERROR_WANT_WRITE == err) { SSL_INCREMENT_DYN_STAT(ssl_error_want_write); - else if (SSL_ERROR_WANT_X509_LOOKUP == err) + } else if (SSL_ERROR_WANT_X509_LOOKUP == err) { SSL_INCREMENT_DYN_STAT(ssl_error_want_x509_lookup); - + TraceOut(trace, get_remote_addr(), get_remote_port(), + "Want X509 lookup"); + } + needs |= EVENTIO_WRITE; r = -EAGAIN; Debug("ssl.error", "SSL_write-SSL_ERROR_WANT_WRITE"); break; } case SSL_ERROR_SYSCALL: + TraceOut(trace, get_remote_addr(), get_remote_port(), + "Syscall Error: %s", strerror(errno)); r = -errno; SSL_INCREMENT_DYN_STAT(ssl_error_syscall); Debug("ssl.error", "SSL_write-SSL_ERROR_SYSCALL"); break; // end of stream case SSL_ERROR_ZERO_RETURN: + TraceOut(trace, get_remote_addr(), get_remote_port(), + "SSL Error: zero return"); r = -errno; SSL_INCREMENT_DYN_STAT(ssl_error_zero_return); Debug("ssl.error", "SSL_write-SSL_ERROR_ZERO_RETURN"); break; case SSL_ERROR_SSL: default: + TraceOut(trace, get_remote_addr(), get_remote_port(), + "SSL Error: sslErr=%d, errno=%d", err, errno); r = -errno; SSL_CLR_ERR_INCR_DYN_STAT(this, ssl_error_ssl, "SSL_write-SSL_ERROR_SSL errno=%d", errno); break; @@ -793,7 +850,7 @@ SSLNetVConnection::SSLNetVConnection() sslHandShakeComplete(false), sslClientConnection(false), sslClientRenegotiationAbort(false), sslSessionCacheHit(false), handShakeBuffer(NULL), handShakeHolder(NULL), handShakeReader(NULL), handShakeBioStored(0), sslPreAcceptHookState(SSL_HOOKS_INIT), sslHandshakeHookState(HANDSHAKE_HOOKS_PRE), npnSet(NULL), npnEndpoint(NULL), - sessionAcceptPtr(NULL), iobuf(NULL), reader(NULL), eosRcvd(false) + sessionAcceptPtr(NULL), iobuf(NULL), reader(NULL), eosRcvd(false), sslTrace(false) { } @@ -885,6 +942,7 @@ SSLNetVConnection::free(EThread *t) eosRcvd = false; sslHandShakeComplete = false; free_handshake_buffers(); + sslTrace=false; if (from_accept_thread) { sslNetVCAllocator.free(this); @@ -937,6 +995,14 @@ SSLNetVConnection::sslStartHandShake(int event, int &err) // to negotiate a SSL session, but it's enough to trampoline us into the SNI callback where we // can select the right server certificate. this->ssl = make_ssl_connection(lookup->defaultContext(), this); +#if !(TS_USE_TLS_SNI) + // set SSL trace + if(SSLConfigParams::ssl_wire_trace_enabled){ + bool trace = computeSSLTrace(); + Debug("ssl", "sslnetvc. setting trace to=%s", trace ? "true" : "false"); + setSSLTrace(trace); + } +#endif } if (this->ssl == NULL) { @@ -1038,6 +1104,8 @@ SSLNetVConnection::sslServerHandShakeEvent(int &err) } ssl_error_t ssl_error = SSLAccept(ssl); + bool trace = getSSLTrace(); + Debug("ssl", "trace=%s", trace ? "TRUE" : "FALSE"); if (ssl_error != SSL_ERROR_NONE) { err = errno; @@ -1067,6 +1135,10 @@ SSLNetVConnection::sslServerHandShakeEvent(int &err) } sslHandShakeComplete = true; + + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL server handshake completed successfully"); + // do we want to include cert info in trace? if (sslHandshakeBeginTime) { const ink_hrtime ssl_handshake_time = Thread::get_hrtime() - sslHandshakeBeginTime; @@ -1108,30 +1180,46 @@ SSLNetVConnection::sslServerHandShakeEvent(int &err) } Debug("ssl", "client selected next protocol '%.*s'", len, proto); + TraceIn(trace, get_remote_addr(), get_remote_port(), + "client selected next protocol'%.*s'", len, proto); } else { Debug("ssl", "client did not select a next protocol"); + TraceIn(trace, get_remote_addr(), get_remote_port(), + "client did not select a next protocol"); } } return EVENT_DONE; case SSL_ERROR_WANT_CONNECT: + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL server handshake ERROR_WANT_CONNECT"); return SSL_HANDSHAKE_WANT_CONNECT; case SSL_ERROR_WANT_WRITE: + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL server handshake ERROR_WANT_WRITE"); return SSL_HANDSHAKE_WANT_WRITE; case SSL_ERROR_WANT_READ: + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL server handshake ERROR_WANT_READ"); return SSL_HANDSHAKE_WANT_READ; // This value is only defined in openssl has been patched to // enable the sni callback to break out of the SSL_accept processing #ifdef SSL_ERROR_WANT_SNI_RESOLVE case SSL_ERROR_WANT_X509_LOOKUP: + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL server handshake ERROR_WANT_X509_LOOKUP"); return EVENT_CONT; case SSL_ERROR_WANT_SNI_RESOLVE: + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL server handshake ERROR_WANT_SNI_RESOLVE"); #elif SSL_ERROR_WANT_X509_LOOKUP case SSL_ERROR_WANT_X509_LOOKUP: + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL server handshake ERROR_WANT_X509_LOOKUP"); #endif #if defined(SSL_ERROR_WANT_SNI_RESOLVE) || defined(SSL_ERROR_WANT_X509_LOOKUP) if (this->attributes == HttpProxyPort::TRANSPORT_BLIND_TUNNEL || TS_SSL_HOOK_OP_TUNNEL == hookOpRequested) { @@ -1145,14 +1233,27 @@ SSLNetVConnection::sslServerHandShakeEvent(int &err) #endif case SSL_ERROR_WANT_ACCEPT: + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL server handshake ERROR_WANT_ACCEPT"); return EVENT_CONT; case SSL_ERROR_SSL: SSL_CLR_ERR_INCR_DYN_STAT(this, ssl_error_ssl, "SSLNetVConnection::sslServerHandShakeEvent, SSL_ERROR_SSL errno=%d", errno); - // fall through + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL server handshake ERROR_SSL"); + return EVENT_ERROR; + case SSL_ERROR_ZERO_RETURN: + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL server handshake ERROR_ZERO_RETURN"); + return EVENT_ERROR; case SSL_ERROR_SYSCALL: + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL server handshake ERROR_SYSCALL"); + return EVENT_ERROR; default: + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL server handshake ERROR_OTHER"); return EVENT_ERROR; } } @@ -1175,6 +1276,9 @@ SSLNetVConnection::sslClientHandShakeEvent(int &err) SSL_set_ex_data(ssl, get_ssl_client_data_index(), this); ssl_error_t ssl_error = SSLConnect(ssl); + bool trace = getSSLTrace(); + Debug("ssl", "trace=%s", trace ? "TRUE" : "FALSE"); + switch (ssl_error) { case SSL_ERROR_NONE: if (is_debug_tag_set("ssl")) { @@ -1192,39 +1296,57 @@ SSLNetVConnection::sslClientHandShakeEvent(int &err) } SSL_INCREMENT_DYN_STAT(ssl_total_success_handshake_count_out_stat); + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL client handshake completed successfully"); + // do we want to include cert info in trace? + sslHandShakeComplete = true; return EVENT_DONE; case SSL_ERROR_WANT_WRITE: Debug("ssl.error", "SSLNetVConnection::sslClientHandShakeEvent, SSL_ERROR_WANT_WRITE"); SSL_INCREMENT_DYN_STAT(ssl_error_want_write); + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL client handshake ERROR_WANT_WRITE"); return SSL_HANDSHAKE_WANT_WRITE; case SSL_ERROR_WANT_READ: SSL_INCREMENT_DYN_STAT(ssl_error_want_read); Debug("ssl.error", "SSLNetVConnection::sslClientHandShakeEvent, SSL_ERROR_WANT_READ"); + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL client handshake ERROR_WANT_READ"); return SSL_HANDSHAKE_WANT_READ; case SSL_ERROR_WANT_X509_LOOKUP: SSL_INCREMENT_DYN_STAT(ssl_error_want_x509_lookup); Debug("ssl.error", "SSLNetVConnection::sslClientHandShakeEvent, SSL_ERROR_WANT_X509_LOOKUP"); + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL client handshake ERROR_WANT_X509_LOOKUP"); break; case SSL_ERROR_WANT_ACCEPT: + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL client handshake ERROR_WANT_ACCEPT"); return SSL_HANDSHAKE_WANT_ACCEPT; case SSL_ERROR_WANT_CONNECT: + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL client handshake ERROR_WANT_CONNECT"); break; case SSL_ERROR_ZERO_RETURN: SSL_INCREMENT_DYN_STAT(ssl_error_zero_return); Debug("ssl.error", "SSLNetVConnection::sslClientHandShakeEvent, EOS"); + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL client handshake EOS"); return EVENT_ERROR; case SSL_ERROR_SYSCALL: err = errno; SSL_INCREMENT_DYN_STAT(ssl_error_syscall); Debug("ssl.error", "SSLNetVConnection::sslClientHandShakeEvent, syscall"); + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL client handshake Syscall Error: %s", strerror(errno)); return EVENT_ERROR; break; @@ -1235,6 +1357,9 @@ SSLNetVConnection::sslClientHandShakeEvent(int &err) // FIXME -- This triggers a retry on cases of cert validation errors.... Debug("ssl", "SSLNetVConnection::sslClientHandShakeEvent, SSL_ERROR_SSL"); SSL_CLR_ERR_INCR_DYN_STAT(this, ssl_error_ssl, "SSLNetVConnection::sslClientHandShakeEvent, SSL_ERROR_SSL errno=%d", errno); + Debug("ssl.error", "SSLNetVConnection::sslClientHandShakeEvent, SSL_ERROR_SSL"); + TraceIn(trace, get_remote_addr(), get_remote_port(), + "SSL client handshake SSL_ERROR"); return EVENT_ERROR; break; } @@ -1375,3 +1500,53 @@ SSLNetVConnection::callHooks(TSHttpHookID eventId) this->sslHandshakeHookState = holdState; return reenabled; } + +bool +SSLNetVConnection::computeSSLTrace() +{ + // this has to happen before the handshake or else sni_servername will be NULL +#if TS_USE_TLS_SNI + bool sni_trace; + if (ssl) { + const char *ssl_servername = SSL_get_servername(ssl, TLSEXT_NAMETYPE_host_name); + char *wire_trace_server_name = SSLConfigParams::ssl_wire_trace_server_name; + Debug("ssl", "for wiretrace, ssl_servername=%s, wire_trace_server_name=%s", ssl_servername, wire_trace_server_name); + sni_trace = ssl_servername && wire_trace_server_name && (0 == strcmp(wire_trace_server_name, ssl_servername)); + } else { + sni_trace = false; + } +#else + bool sni_trace = false; +#endif + + //count based on ip only if they set an IP value + const sockaddr *remote_addr = get_remote_addr(); + bool ip_trace = false; + if (SSLConfigParams::ssl_wire_trace_ip) { + ip_trace = (*SSLConfigParams::ssl_wire_trace_ip == remote_addr); + } + + //count based on percentage + int percentage = SSLConfigParams::ssl_wire_trace_percentage; + int random; + bool trace; + + // we only generate random numbers as needed (to maintain correct percentage) + if (SSLConfigParams::ssl_wire_trace_server_name && SSLConfigParams::ssl_wire_trace_ip) { + random = this_ethread()->generator.random() % 100; // range [0-99] + trace = sni_trace && ip_trace && (percentage > random); + } else if (SSLConfigParams::ssl_wire_trace_server_name) { + random = this_ethread()->generator.random() % 100; // range [0-99] + trace = sni_trace && (percentage > random); + } else if (SSLConfigParams::ssl_wire_trace_ip) { + random = this_ethread()->generator.random() % 100; // range [0-99] + trace = ip_trace && (percentage > random); + } else { + random = this_ethread()->generator.random() % 100; // range [0-99] + trace = percentage > random; + } + + Debug("ssl", "ssl_netvc random=%d, trace=%s", random, trace ? "TRUE" : "FALSE"); + + return trace; +} http://git-wip-us.apache.org/repos/asf/trafficserver/blob/6e3ce502/iocore/net/SSLUtils.cc ---------------------------------------------------------------------- diff --git a/iocore/net/SSLUtils.cc b/iocore/net/SSLUtils.cc index c4055e0..db89fbd 100644 --- a/iocore/net/SSLUtils.cc +++ b/iocore/net/SSLUtils.cc @@ -281,7 +281,14 @@ set_context_cert(SSL *ssl) bool found = true; int retval = 1; - Debug("ssl", "set_context_cert ssl=%p server=%s handshake_complete=%d", ssl, servername, netvc->getSSLHandShakeComplete()); + Debug("ssl", "set_context_cert ssl=%p server=%s handshake_complete=%d", ssl, servername, + netvc->getSSLHandShakeComplete()); + // set SSL trace (we do this a little later in the USE_TLS_SNI case so we can get the servername + if(SSLConfigParams::ssl_wire_trace_enabled){ + bool trace = netvc->computeSSLTrace(); + Debug("ssl", "sslnetvc. setting trace to=%s", trace ? "true" : "false"); + netvc->setSSLTrace(trace); + } // catch the client renegotiation early on if (SSLConfigParams::ssl_allow_client_renegotiation == false && netvc->getSSLHandShakeComplete()) { http://git-wip-us.apache.org/repos/asf/trafficserver/blob/6e3ce502/iocore/net/UnixNetVConnection.cc ---------------------------------------------------------------------- diff --git a/iocore/net/UnixNetVConnection.cc b/iocore/net/UnixNetVConnection.cc index 9087b19..7e871dd 100644 --- a/iocore/net/UnixNetVConnection.cc +++ b/iocore/net/UnixNetVConnection.cc @@ -22,6 +22,8 @@ */ #include "P_Net.h" +#include "libts.h" +#include "Log.h" #define STATE_VIO_OFFSET ((uintptr_t) & ((NetState *)0)->vio) #define STATE_FROM_VIO(_x) ((NetState *)(((char *)(_x)) - STATE_VIO_OFFSET)) @@ -301,6 +303,27 @@ read_from_net(NetHandler *nh, UnixNetVConnection *vc, EThread *thread) r = socketManager.readv(vc->con.fd, &tiovec[0], niov); } NET_INCREMENT_DYN_STAT(net_calls_to_read_stat); + + if (vc->origin_trace) { + char origin_trace_ip[INET6_ADDRSTRLEN]; + + ats_ip_ntop(vc->origin_trace_addr, origin_trace_ip, sizeof (origin_trace_ip)); + + if (r > 0) { + TraceIn((vc->origin_trace), vc->get_remote_addr(), vc->get_remote_port(), + "CLIENT %s:%d\tbytes=%d\n%.*s", origin_trace_ip, vc->origin_trace_port, (int)r, + (int)r, (char *)tiovec[0].iov_base); + + } else if (r == 0) { + TraceIn((vc->origin_trace), vc->get_remote_addr(), vc->get_remote_port(), + "CLIENT %s:%d closed connection", origin_trace_ip, vc->origin_trace_port); + } else { + TraceIn((vc->origin_trace), vc->get_remote_addr(), vc->get_remote_port(), + "CLIENT %s:%d error=%s", origin_trace_ip, vc->origin_trace_port, strerror(errno)); + } + + } + total_read += rattempted; } while (rattempted && r == rattempted && total_read < toread); @@ -857,7 +880,8 @@ UnixNetVConnection::UnixNetVConnection() #else next_inactivity_timeout_at(0), next_activity_timeout_at(0), #endif - nh(NULL), id(0), flags(0), recursion(0), submit_time(0), oob_ptr(0), from_accept_thread(false) + nh(NULL), id(0), flags(0), recursion(0), submit_time(0), oob_ptr(0), from_accept_thread(false), + origin_trace(false), origin_trace_addr(NULL), origin_trace_port(0) { memset(&local_addr, 0, sizeof local_addr); memset(&server_addr, 0, sizeof server_addr); @@ -938,6 +962,26 @@ UnixNetVConnection::load_buffer_and_write(int64_t towrite, int64_t &wattempted, r = socketManager.write(con.fd, tiovec[0].iov_base, tiovec[0].iov_len); else r = socketManager.writev(con.fd, &tiovec[0], niov); + + if (origin_trace) { + char origin_trace_ip[INET6_ADDRSTRLEN]; + ats_ip_ntop(origin_trace_addr, origin_trace_ip, sizeof (origin_trace_ip)); + + if (r > 0) { + TraceOut(origin_trace, get_remote_addr(), get_remote_port(), + "CLIENT %s:%d\tbytes=%d\n%.*s", origin_trace_ip, origin_trace_port, (int)r, + (int)r, (char *)tiovec[0].iov_base); + + } else if (r == 0) { + TraceOut(origin_trace, get_remote_addr(), get_remote_port(), + "CLIENT %s:%d closed connection", origin_trace_ip, origin_trace_port); + } else { + TraceOut(origin_trace, get_remote_addr(), get_remote_port(), + "CLIENT %s:%d error=%s", origin_trace_ip, origin_trace_port, strerror(errno)); + } + + } + ProxyMutex *mutex = thread->mutex; NET_INCREMENT_DYN_STAT(net_calls_to_write_stat); } while (r == wattempted && total_written < towrite); http://git-wip-us.apache.org/repos/asf/trafficserver/blob/6e3ce502/mgmt/RecordsConfig.cc ---------------------------------------------------------------------- diff --git a/mgmt/RecordsConfig.cc b/mgmt/RecordsConfig.cc index 5626f9d..c967acd 100644 --- a/mgmt/RecordsConfig.cc +++ b/mgmt/RecordsConfig.cc @@ -1284,6 +1284,14 @@ static const RecordElement RecordsConfig[] = , {RECT_CONFIG, "proxy.config.ssl.handshake_timeout_in", RECD_INT, "0", RECU_RESTART_TS, RR_NULL, RECC_INT, "[0-65535]", RECA_NULL} , + {RECT_CONFIG, "proxy.config.ssl.wire_trace_enabled", RECD_INT, "0", RECU_RESTART_TS, RR_NULL, RECC_INT, "[0-2]", RECA_NULL} + , + {RECT_CONFIG, "proxy.config.ssl.wire_trace_addr", RECD_STRING, NULL , RECU_RESTART_TS, RR_NULL, RECC_IP, "[0-255]\\.[0-255]\\.[0-255]\\.[0-255]", RECA_NULL} + , + {RECT_CONFIG, "proxy.config.ssl.wire_trace_percentage", RECD_INT, "0", RECU_RESTART_TS, RR_NULL, RECC_INT, "[0-100]", RECA_NULL} + , + {RECT_CONFIG, "proxy.config.ssl.wire_trace_server_name", RECD_STRING, NULL , RECU_RESTART_TS, RR_NULL, RECC_STR, ".*", RECA_NULL} + , //############################################################################## //# //# OCSP (Online Certificate Status Protocol) Stapling Configuration http://git-wip-us.apache.org/repos/asf/trafficserver/blob/6e3ce502/proxy/http/HttpSM.cc ---------------------------------------------------------------------- diff --git a/proxy/http/HttpSM.cc b/proxy/http/HttpSM.cc index 985d718..044817b 100644 --- a/proxy/http/HttpSM.cc +++ b/proxy/http/HttpSM.cc @@ -38,6 +38,7 @@ #include "ReverseProxy.h" #include "RemapProcessor.h" #include "Transform.h" +#include "P_SSLConfig.h" #include "HttpPages.h" @@ -5378,9 +5379,8 @@ HttpSM::do_setup_post_tunnel(HttpVC_t to_vc_type) // Next order of business if copy the remaining data from the // header buffer into new buffer - // - client_request_body_bytes = post_buffer->write(ua_buffer_reader, chunked ? ua_buffer_reader->read_avail() : post_bytes); + ua_buffer_reader->consume(client_request_body_bytes); p = tunnel.add_producer(ua_entry->vc, post_bytes - transfered_bytes, buf_start, &HttpSM::tunnel_handler_post_ua, HT_HTTP_CLIENT, "user agent post"); @@ -5602,6 +5602,31 @@ HttpSM::attach_server_session(HttpServerSession *s) server_entry->vc = server_session; server_entry->vc_type = HTTP_SERVER_VC; server_entry->vc_handler = &HttpSM::state_send_server_request_header; + + // es - is this a concern here in HttpSM? Does it belong somewhere else? + // Get server and client connections + UnixNetVConnection *server_vc = (UnixNetVConnection *)(server_session->get_netvc()); + UnixNetVConnection *client_vc = (UnixNetVConnection *)(ua_session->get_netvc()); + SSLNetVConnection *ssl_vc = dynamic_cast<SSLNetVConnection *>(client_vc); + if(ssl_vc != NULL) { //if incoming connection is SSL + bool client_trace = ssl_vc->getSSLTrace(); + if(client_trace) { + // get remote address and port to mark corresponding traces + const sockaddr *remote_addr = ssl_vc->get_remote_addr(); + uint16_t remote_port = ssl_vc->get_remote_port(); + server_vc->setOriginTrace(true); + server_vc->setOriginTraceAddr(remote_addr); + server_vc->setOriginTracePort(remote_port); + } else { + server_vc->setOriginTrace(false); + server_vc->setOriginTraceAddr(NULL); + server_vc->setOriginTracePort(0); + } + } else { + server_vc->setOriginTrace(false); + server_vc->setOriginTraceAddr(NULL); + server_vc->setOriginTracePort(0); + } // Initiate a read on the session so that the SM and not // session manager will get called back if the timeout occurs http://git-wip-us.apache.org/repos/asf/trafficserver/blob/6e3ce502/proxy/logging/Log.cc ---------------------------------------------------------------------- diff --git a/proxy/logging/Log.cc b/proxy/logging/Log.cc index 482d01d..f565ea0 100644 --- a/proxy/logging/Log.cc +++ b/proxy/logging/Log.cc @@ -1014,6 +1014,55 @@ Log::va_error(const char *format, va_list ap) } /*------------------------------------------------------------------------- + Log::trace + + These functions are used for wiretracing of incoming SSL connections. + They are an extension of the existing Log::error functionality but with + special formatting and handling of the non null terminated buffer. + -------------------------------------------------------------------------*/ + +void +Log::trace_in(const sockaddr *peer_addr, uint16_t peer_port, + const char *format_string, ...) +{ + va_list ap; + va_start(ap, format_string); + trace_va(true, peer_addr, peer_port, format_string, ap); + va_end(ap); +} + +void +Log::trace_out(const sockaddr *peer_addr, uint16_t peer_port, + const char *format_string, ...) +{ + va_list ap; + va_start(ap, format_string); + trace_va(false, peer_addr, peer_port, format_string, ap); + va_end(ap); +} + +void +Log::trace_va(bool in, const sockaddr *peer_addr, uint16_t peer_port, + const char *format_string, va_list ap) +{ + if (!peer_addr || !format_string) { + return; + } + + char ip[INET6_ADDRSTRLEN]; + ats_ip_ntop(peer_addr, ip, sizeof(ip)); + + struct timeval tp; + ink_gethrtimeofday(&tp, NULL); + + Log::error("[%9d.%03d] Trace {0x%" PRIx64 "} %s %s:%d: ", + (int) tp.tv_sec, (int) (tp.tv_usec / 1000), + (uint64_t) pthread_self(), in ? "RECV" : "SEND", ip, peer_port); + Log::va_error(format_string, ap); + Log::error("[End Trace]\n"); +} + +/*------------------------------------------------------------------------- Log::preproc_thread_main This function defines the functionality of the logging flush prepare http://git-wip-us.apache.org/repos/asf/trafficserver/blob/6e3ce502/proxy/logging/Log.h ---------------------------------------------------------------------- diff --git a/proxy/logging/Log.h b/proxy/logging/Log.h index fb194c9..f726d32 100644 --- a/proxy/logging/Log.h +++ b/proxy/logging/Log.h @@ -417,7 +417,17 @@ public: inkcoreapi static int access(LogAccess *lad); inkcoreapi static int va_error(const char *format, va_list ap); inkcoreapi static int error(const char *format, ...) TS_PRINTFLIKE(1, 2); - + + ///////////////////////////////////////////////////////////////////////// + // 'Wire tracing' enabled by source ip or by percentage of connections // + ///////////////////////////////////////////////////////////////////////// + static void trace_in(const sockaddr *peer_addr, uint16_t peer_port, + const char *format_string, ...) TS_PRINTFLIKE(3, 4); + static void trace_out(const sockaddr *peer_addr, uint16_t peer_port, + const char *format_string, ...) TS_PRINTFLIKE(3, 4); + static void trace_va(bool in, const sockaddr *peer_addr, uint16_t peer_port, + const char *format_string, va_list ap); + // public data members inkcoreapi static LogObject *error_log; static LogConfig *config; @@ -474,4 +484,7 @@ LogRollingEnabledIsValid(int enabled) return (enabled >= Log::NO_ROLLING || enabled < Log::INVALID_ROLLING_VALUE); } +#define TraceIn(flag, ...) if (flag) Log::trace_in(__VA_ARGS__) +#define TraceOut(flag, ...) if (flag) Log::trace_out(__VA_ARGS__) + #endif
