From 378c8c03ef3825a404e04d040e0498219b9509b8 Mon Sep 17 00:00:00 2001 From: Soner Tari Date: Sun, 23 Jul 2017 01:15:59 +0300 Subject: [PATCH] Fix/improve logging, clean-up --- pxyconn.c | 138 ++++++++++++++++++++++++++++++++++++++++------------ pxyconn.h | 2 + pxythrmgr.c | 2 +- 3 files changed, 109 insertions(+), 33 deletions(-) diff --git a/pxyconn.c b/pxyconn.c index 7dd6068..ff395f6 100644 --- a/pxyconn.c +++ b/pxyconn.c @@ -436,6 +436,12 @@ pxy_conn_ctx_free(pxy_conn_ctx_t *ctx) if (ctx->child_addr_str) { free(ctx->child_addr_str); } + if (ctx->srv_dst_ssl_version) { + free(ctx->srv_dst_ssl_version); + } + if (ctx->srv_dst_ssl_cipher) { + free(ctx->srv_dst_ssl_cipher); + } free(ctx); } @@ -603,8 +609,8 @@ pxy_log_connect_nonhttp(pxy_conn_ctx_t *ctx) STRORDASH(ctx->ssl_names), SSL_get_version(ctx->src.ssl), SSL_get_cipher(ctx->src.ssl), - !ctx->srv_dst.closed ? SSL_get_version(ctx->srv_dst.ssl):"?", - !ctx->srv_dst.closed ? SSL_get_cipher(ctx->srv_dst.ssl):"?", + !ctx->srv_dst.closed ? SSL_get_version(ctx->srv_dst.ssl):ctx->srv_dst_ssl_version, + !ctx->srv_dst.closed ? SSL_get_cipher(ctx->srv_dst.ssl):ctx->srv_dst_ssl_cipher, STRORDASH(ctx->origcrtfpr), STRORDASH(ctx->usedcrtfpr) #ifdef HAVE_LOCAL_PROCINFO @@ -708,8 +714,8 @@ pxy_log_connect_http(pxy_conn_ctx_t *ctx) STRORDASH(ctx->ssl_names), SSL_get_version(ctx->src.ssl), SSL_get_cipher(ctx->src.ssl), - !ctx->srv_dst.closed ? SSL_get_version(ctx->srv_dst.ssl):"?", - !ctx->srv_dst.closed ? SSL_get_cipher(ctx->srv_dst.ssl):"?", + !ctx->srv_dst.closed ? SSL_get_version(ctx->srv_dst.ssl):ctx->srv_dst_ssl_version, + !ctx->srv_dst.closed ? SSL_get_cipher(ctx->srv_dst.ssl):ctx->srv_dst_ssl_cipher, STRORDASH(ctx->origcrtfpr), STRORDASH(ctx->usedcrtfpr), #ifdef HAVE_LOCAL_PROCINFO @@ -1522,10 +1528,8 @@ pxy_http_reqhdr_filter_line(const char *line, pxy_conn_ctx_t *ctx, int child) static char * pxy_http_resphdr_filter_line(const char *line, pxy_conn_ctx_t *ctx) { - log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_http_resphdr_filter_line: ENTER, fd=%d\n", ctx->fd); /* parse information for connect log */ if (!ctx->http_status_code) { - log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_http_resphdr_filter_line: first line, fd=%d\n", ctx->fd); /* first line */ char *space1, *space2; @@ -1534,9 +1538,7 @@ pxy_http_resphdr_filter_line(const char *line, pxy_conn_ctx_t *ctx) if (!space1 || !!strncmp(line, "HTTP", 4)) { /* not HTTP or HTTP/0.9 */ ctx->seen_resp_header = 1; - log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_http_resphdr_filter_line: first line not HTTP or HTTP/0.9, fd=%d\n", ctx->fd); } else { - log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_http_resphdr_filter_line: first line else, fd=%d\n", ctx->fd); size_t len_code, len_text; if (space2) { @@ -1561,7 +1563,6 @@ pxy_http_resphdr_filter_line(const char *line, pxy_conn_ctx_t *ctx) ctx->http_status_text[len_text] = '\0'; } } else { - log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_http_resphdr_filter_line: NOT first line, fd=%d\n", ctx->fd); /* not first line */ if (!ctx->http_content_length && !strncasecmp(line, "Content-Length:", 15)) { @@ -1569,7 +1570,6 @@ pxy_http_resphdr_filter_line(const char *line, pxy_conn_ctx_t *ctx) strdup(util_skipws(line + 15)); if (!ctx->http_content_length) { ctx->enomem = 1; - log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_http_resphdr_filter_line: NOT first line http_content_length, fd=%d\n", ctx->fd); return NULL; } } else if ( @@ -1584,13 +1584,10 @@ pxy_http_resphdr_filter_line(const char *line, pxy_conn_ctx_t *ctx) /* Alternate Protocol * remove to prevent switching to QUIC, SPDY et al */ !strncasecmp(line, "Alternate-Protocol:", 19)) { - log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_http_resphdr_filter_line: NOT first line HSTS, fd=%d\n", ctx->fd); return NULL; } else if (line[0] == '\0') { - log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_http_resphdr_filter_line: NOT first line zero, fd=%d\n", ctx->fd); ctx->seen_resp_header = 1; } - log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_http_resphdr_filter_line: NOT first line exit, fd=%d\n", ctx->fd); } return (char*)line; @@ -1834,7 +1831,6 @@ pxy_get_event_name_child(struct bufferevent *bev, pxy_conn_child_ctx_t *ctx) static void pxy_http_reqhdr_filter(struct evbuffer *inbuf, struct evbuffer *outbuf, struct bufferevent *bev, pxy_conn_ctx_t *ctx, pxy_conn_ctx_t *parent, int child) { - log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_http_reqhdr_filter: HTTP Request Header, fd=%d\n", ctx->fd); logbuf_t *lb = NULL, *tail = NULL; int inserted_sslproxy_addr = 0; char *line; @@ -1868,7 +1864,7 @@ pxy_http_reqhdr_filter(struct evbuffer *inbuf, struct evbuffer *outbuf, struct b if (!child && !inserted_sslproxy_addr) { inserted_sslproxy_addr = 1; - log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_http_reqhdr_filter: src line, fd=%d: %s\n", ctx->fd, ctx->child_addr_str); + log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_http_reqhdr_filter: src INSERT sslproxy_addr line, fd=%d: %s\n", ctx->fd, ctx->child_addr_str); evbuffer_add_printf(outbuf, "%s\r\n", ctx->child_addr_str); } @@ -1881,7 +1877,7 @@ pxy_http_reqhdr_filter(struct evbuffer *inbuf, struct evbuffer *outbuf, struct b } } if (lb && WANT_CONTENT_LOG(parent)) { - if (log_content_submit(ctx->logctx, lb, + if (log_content_submit(parent->logctx, lb, 1/*req*/) == -1) { logbuf_free(lb); log_err_printf("Warning: Content log " @@ -1907,7 +1903,7 @@ pxy_http_reqhdr_filter(struct evbuffer *inbuf, struct evbuffer *outbuf, struct b logbuf_t *lb; lb = logbuf_new_alloc(evbuffer_get_length(inbuf), NULL, NULL); if (lb && (evbuffer_copyout(inbuf, lb->buf, lb->sz) != -1)) { - if (log_content_submit(ctx->logctx, lb, + if (log_content_submit(parent->logctx, lb, (bev == ctx->src.bev)) == -1) { logbuf_free(lb); log_err_printf("Warning: Content log " @@ -1921,7 +1917,7 @@ leave: } static void -pxy_http_resphdr_filter(struct evbuffer *inbuf, struct evbuffer *outbuf, struct bufferevent *bev, pxy_conn_ctx_t *ctx, pxy_conn_ctx_t *parent) +pxy_http_resphdr_filter(struct evbuffer *inbuf, struct evbuffer *outbuf, struct bufferevent *bev, pxy_conn_ctx_t *ctx, pxy_conn_ctx_t *parent, int child) { logbuf_t *lb = NULL, *tail = NULL; char *line; @@ -1955,14 +1951,14 @@ pxy_http_resphdr_filter(struct evbuffer *inbuf, struct evbuffer *outbuf, struct free(line); if (ctx->seen_resp_header) { /* response header complete: log connection */ - if (WANT_CONNECT_LOG(parent)) { + if (!child && WANT_CONNECT_LOG(parent)) { pxy_log_connect_http(parent); } break; } } if (lb && WANT_CONTENT_LOG(parent)) { - if (log_content_submit(ctx->logctx, lb, + if (log_content_submit(parent->logctx, lb, 0/*resp*/) == -1) { logbuf_free(lb); log_err_printf("Warning: Content log " @@ -1988,7 +1984,7 @@ pxy_http_resphdr_filter(struct evbuffer *inbuf, struct evbuffer *outbuf, struct logbuf_t *lb; lb = logbuf_new_alloc(evbuffer_get_length(inbuf), NULL, NULL); if (lb && (evbuffer_copyout(inbuf, lb->buf, lb->sz) != -1)) { - if (log_content_submit(ctx->logctx, lb, + if (log_content_submit(parent->logctx, lb, (bev == ctx->src.bev)) == -1) { logbuf_free(lb); log_err_printf("Warning: Content log " @@ -2002,8 +1998,21 @@ leave: } static void -pxy_process_response(struct evbuffer *inbuf, struct evbuffer *outbuf, pxy_conn_ctx_t *ctx) +pxy_process_response(struct evbuffer *inbuf, struct evbuffer *outbuf, struct bufferevent *bev, pxy_conn_ctx_t *ctx, pxy_conn_ctx_t *parent) { + if (WANT_CONTENT_LOG(parent)) { + logbuf_t *lb; + lb = logbuf_new_alloc(evbuffer_get_length(inbuf), NULL, NULL); + if (lb && (evbuffer_copyout(inbuf, lb->buf, lb->sz) != -1)) { + if (log_content_submit(parent->logctx, lb, + (bev == ctx->src.bev)) == -1) { + logbuf_free(lb); + log_err_printf("Warning: Content log " + "submission failed\n"); + } + } + } + size_t packet_size = evbuffer_get_length(inbuf); char *packet = malloc(packet_size); if (!packet) { @@ -2075,9 +2084,22 @@ pxy_bev_readcb(struct bufferevent *bev, void *arg) pxy_http_reqhdr_filter(inbuf, outbuf, bev, ctx, ctx, 0); } else { log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_bev_readcb: HTTP Request Body size=%lu, fd=%d\n", evbuffer_get_length(inbuf), ctx->fd); - evbuffer_add_buffer(outbuf, inbuf); + goto leave; } } else { + if (WANT_CONTENT_LOG(ctx)) { + logbuf_t *lb; + lb = logbuf_new_alloc(evbuffer_get_length(inbuf), NULL, NULL); + if (lb && (evbuffer_copyout(inbuf, lb->buf, lb->sz) != -1)) { + if (log_content_submit(ctx->logctx, lb, + (bev == ctx->src.bev)) == -1) { + logbuf_free(lb); + log_err_printf("Warning: Content log " + "submission failed\n"); + } + } + } + log_dbg_level_printf(LOG_DBG_MODE_FINER, ">>>>>,,,,,,,,,,,,,,,,,,,,,,, pxy_bev_readcb: custom_field= %s\n", ctx->child_addr_str); size_t packet_size = evbuffer_get_length(inbuf); @@ -2142,16 +2164,33 @@ pxy_bev_readcb(struct bufferevent *bev, void *arg) if (ctx->spec->http) { if (!ctx->seen_resp_header) { log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_bev_readcb: HTTP Response Header size=%lu, fd=%d\n", evbuffer_get_length(inbuf), ctx->fd); - pxy_http_resphdr_filter(inbuf, outbuf, bev, ctx, ctx); + pxy_http_resphdr_filter(inbuf, outbuf, bev, ctx, ctx, 0); } else { log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_bev_readcb: HTTP Response Body size=%lu, fd=%d\n", evbuffer_get_length(inbuf), ctx->fd); - evbuffer_add_buffer(outbuf, inbuf); + goto leave; } } else { - pxy_process_response(inbuf, outbuf, ctx); + pxy_process_response(inbuf, outbuf, bev, ctx, ctx); } } + goto watermark; +leave: + if (WANT_CONTENT_LOG(ctx)) { + logbuf_t *lb; + lb = logbuf_new_alloc(evbuffer_get_length(inbuf), NULL, NULL); + if (lb && (evbuffer_copyout(inbuf, lb->buf, lb->sz) != -1)) { + if (log_content_submit(ctx->logctx, lb, + (bev == ctx->src.bev)) == -1) { + logbuf_free(lb); + log_err_printf("Warning: Content log " + "submission failed\n"); + } + } + } + evbuffer_add_buffer(outbuf, inbuf); + +watermark: if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT) { /* temporarily disable data source; * set an appropriate watermark. */ @@ -2202,9 +2241,22 @@ pxy_bev_readcb_child(struct bufferevent *bev, void *arg) pxy_http_reqhdr_filter(inbuf, outbuf, bev, (pxy_conn_ctx_t *)ctx, parent, 1); } else { log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_bev_readcb_child: HTTP Request Body size=%lu, fd=%d\n", evbuffer_get_length(inbuf), ctx->fd); - evbuffer_add_buffer(outbuf, inbuf); + goto leave; } } else { + if (WANT_CONTENT_LOG(parent)) { + logbuf_t *lb; + lb = logbuf_new_alloc(evbuffer_get_length(inbuf), NULL, NULL); + if (lb && (evbuffer_copyout(inbuf, lb->buf, lb->sz) != -1)) { + if (log_content_submit(parent->logctx, lb, + (bev == ctx->src.bev)) == -1) { + logbuf_free(lb); + log_err_printf("Warning: Content log " + "submission failed\n"); + } + } + } + size_t packet_size = evbuffer_get_length(inbuf); // ATTENTION: +1 is for null termination char *packet = malloc(packet_size + 1); @@ -2264,16 +2316,33 @@ pxy_bev_readcb_child(struct bufferevent *bev, void *arg) if (parent->spec->http) { if (!ctx->seen_resp_header) { log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_bev_readcb_child: HTTP Response Header size=%lu, fd=%d\n", evbuffer_get_length(inbuf), ctx->fd); - pxy_http_resphdr_filter(inbuf, outbuf, bev, (pxy_conn_ctx_t *)ctx, parent); + pxy_http_resphdr_filter(inbuf, outbuf, bev, (pxy_conn_ctx_t *)ctx, parent, 1); } else { log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>>>> pxy_bev_readcb_child: HTTP Response Body size=%lu, fd=%d\n", evbuffer_get_length(inbuf), ctx->fd); - evbuffer_add_buffer(outbuf, inbuf); + goto leave; } } else { - pxy_process_response(inbuf, outbuf, (pxy_conn_ctx_t *)ctx); + pxy_process_response(inbuf, outbuf, bev, (pxy_conn_ctx_t *)ctx, parent); } } + goto watermark; +leave: + if (WANT_CONTENT_LOG(parent)) { + logbuf_t *lb; + lb = logbuf_new_alloc(evbuffer_get_length(inbuf), NULL, NULL); + if (lb && (evbuffer_copyout(inbuf, lb->buf, lb->sz) != -1)) { + if (log_content_submit(parent->logctx, lb, + (bev == ctx->src.bev)) == -1) { + logbuf_free(lb); + log_err_printf("Warning: Content log " + "submission failed\n"); + } + } + } + evbuffer_add_buffer(outbuf, inbuf); + +watermark: if (evbuffer_get_length(outbuf) >= OUTBUF_LIMIT) { /* temporarily disable data source; * set an appropriate watermark. */ @@ -2569,8 +2638,13 @@ pxy_connected_enable(struct bufferevent *bev, pxy_conn_ctx_t *ctx, char *event_n } } - // @todo Closing srv_dst causes TCP conns to stall sometimes (SSL cons were ok)? - // @attention Free the dst of the parent ctx asap, we don't need it, but we need its fd + // @attention Free the srv_dst of the parent ctx asap, we don't need it, but we need its fd + // So save its ssl info for logging + if (ctx->srv_dst.ssl) { + ctx->srv_dst_ssl_version = strdup(SSL_get_version(ctx->srv_dst.ssl)); + ctx->srv_dst_ssl_cipher = strdup(SSL_get_cipher(ctx->srv_dst.ssl)); + } + pxy_conn_desc_t *srv_dst = &ctx->srv_dst; if (srv_dst->bev) { log_dbg_level_printf(LOG_DBG_MODE_FINER, ">>>>>=================================== pxy_connected_enable: evutil_closesocket srv_dst->bev, fd=%d\n", bufferevent_getfd(srv_dst->bev)); diff --git a/pxyconn.h b/pxyconn.h index 696cf9d..eaf8d5f 100644 --- a/pxyconn.h +++ b/pxyconn.h @@ -104,6 +104,8 @@ struct pxy_conn_ctx { unsigned int clienthello_found : 1; /* 1 if conn upgrade to SSL */ struct pxy_conn_desc srv_dst; + char *srv_dst_ssl_version; + char *srv_dst_ssl_cipher; struct event *ev; diff --git a/pxythrmgr.c b/pxythrmgr.c index c36868d..3c0c733 100644 --- a/pxythrmgr.c +++ b/pxythrmgr.c @@ -124,7 +124,7 @@ pxy_thrmgr_print_thr_info(pxy_thr_ctx_t *tctx) } } - log_dbg_level_printf(LOG_DBG_MODE_FINE, ">>> pxy_thrmgr_print_thr_info: EXIT\n"); + log_dbg_level_printf(LOG_DBG_MODE_FINEST, ">>> pxy_thrmgr_print_thr_info: EXIT\n"); } /*