From 01b9f2e551218d00748d542b75da3660fe10f8c6 Mon Sep 17 00:00:00 2001 From: Stefan Fritsch Date: Sun, 6 Jun 2010 17:07:12 +0000 Subject: [PATCH] - Be less verbose at levels INFO and DEBUG in mod_proxy* and mod_ssl - Add some trace logging to core and http git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@951900 13f79535-47bb-0310-9956-ffa450edef68 --- modules/http/http_filters.c | 12 +++++ modules/proxy/mod_proxy_ajp.c | 2 +- modules/proxy/mod_proxy_balancer.c | 2 +- modules/proxy/mod_proxy_connect.c | 22 ++++----- modules/proxy/mod_proxy_fcgi.c | 2 +- modules/proxy/mod_proxy_ftp.c | 41 ++++++++-------- modules/proxy/mod_proxy_http.c | 22 ++++++--- modules/proxy/proxy_util.c | 36 +++++++------- modules/ssl/ssl_engine_init.c | 10 ++-- modules/ssl/ssl_engine_io.c | 16 +++--- modules/ssl/ssl_engine_kernel.c | 78 +++++++++++++++--------------- modules/ssl/ssl_engine_rand.c | 2 +- server/protocol.c | 6 +++ 13 files changed, 139 insertions(+), 112 deletions(-) diff --git a/modules/http/http_filters.c b/modules/http/http_filters.c index 2fc2f40e75..4ab767a97c 100644 --- a/modules/http/http_filters.c +++ b/modules/http/http_filters.c @@ -804,6 +804,18 @@ static apr_status_t send_all_header_fields(header_struct *h, t_elt++; } while (t_elt < t_end); + if (APLOGrtrace4(r)) { + ap_log_rerror(APLOG_MARK, APLOG_TRACE4, 0, r, + "Headers sent to client:"); + t_elt = (const apr_table_entry_t *)(elts->elts); + do { + ap_log_rerror(APLOG_MARK, APLOG_TRACE4, 0, r, "%s: %s", + ap_escape_logitem(r->pool, t_elt->key), + ap_escape_logitem(r->pool, t_elt->val)); + t_elt++; + } while (t_elt < t_end); + } + #if APR_CHARSET_EBCDIC { apr_size_t len; diff --git a/modules/proxy/mod_proxy_ajp.c b/modules/proxy/mod_proxy_ajp.c index 929b09c360..7668f0037b 100644 --- a/modules/proxy/mod_proxy_ajp.c +++ b/modules/proxy/mod_proxy_ajp.c @@ -42,7 +42,7 @@ static int proxy_ajp_canon(request_rec *r, char *url) return DECLINED; } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, r->server, "proxy: AJP: canonicalising URL %s", url); /* diff --git a/modules/proxy/mod_proxy_balancer.c b/modules/proxy/mod_proxy_balancer.c index 2ad43601b5..e2bd8652ab 100644 --- a/modules/proxy/mod_proxy_balancer.c +++ b/modules/proxy/mod_proxy_balancer.c @@ -41,7 +41,7 @@ static int proxy_balancer_canon(request_rec *r, char *url) return DECLINED; } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, r->server, "proxy: BALANCER: canonicalising URL %s", url); /* do syntatic check. diff --git a/modules/proxy/mod_proxy_connect.c b/modules/proxy/mod_proxy_connect.c index f90d6b6e67..e90cb5c62f 100644 --- a/modules/proxy/mod_proxy_connect.c +++ b/modules/proxy/mod_proxy_connect.c @@ -138,8 +138,8 @@ static int proxy_connect_canon(request_rec *r, char *url) if (r->method_number != M_CONNECT) { return DECLINED; } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, - "proxy: CONNECT: canonicalising URL %s", url); + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, r->server, + "proxy: CONNECT: canonicalising URL %s", url); return OK; } @@ -225,11 +225,11 @@ static int proxy_connect_handler(request_rec *r, proxy_worker *worker, /* is this for us? */ if (r->method_number != M_CONNECT) { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, r->server, "proxy: CONNECT: declining URL %s", url); return DECLINED; } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, r->server, "proxy: CONNECT: serving URL %s", url); @@ -271,7 +271,7 @@ static int proxy_connect_handler(request_rec *r, proxy_worker *worker, connectport = uri.port; connect_addr = uri_addr; } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, r->server, "proxy: CONNECT: connecting to remote proxy %s on port %d", connectname, connectport); @@ -326,7 +326,7 @@ static int proxy_connect_handler(request_rec *r, proxy_worker *worker, } /* setup polling for connection */ - ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, + ap_log_rerror(APLOG_MARK, APLOG_TRACE2, 0, r, "proxy: CONNECT: setting up poll()"); if ((rv = apr_pollset_create(&pollset, 2, r->pool, 0)) != APR_SUCCESS) { @@ -373,7 +373,7 @@ static int proxy_connect_handler(request_rec *r, proxy_worker *worker, return HTTP_INTERNAL_SERVER_ERROR; } - ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, + ap_log_rerror(APLOG_MARK, APLOG_TRACE3, 0, r, "proxy: CONNECT: connection complete to %pI (%s)", connect_addr, connectname); @@ -384,7 +384,7 @@ static int proxy_connect_handler(request_rec *r, proxy_worker *worker, if (proxyport) { /* FIXME: Error checking ignored. */ - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE2, 0, r->server, "proxy: CONNECT: sending the CONNECT request" " to the remote proxy"); ap_fprintf(backconn->output_filters, bb, @@ -394,7 +394,7 @@ static int proxy_connect_handler(request_rec *r, proxy_worker *worker, ap_fflush(backconn->output_filters, bb); } else { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, r->server, "proxy: CONNECT: Returning 200 OK Status"); nbytes = apr_snprintf(buffer, sizeof(buffer), "HTTP/1.0 200 Connection Established" CRLF); @@ -417,7 +417,7 @@ static int proxy_connect_handler(request_rec *r, proxy_worker *worker, #endif } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE2, 0, r->server, "proxy: CONNECT: setting up poll()"); /* @@ -490,7 +490,7 @@ static int proxy_connect_handler(request_rec *r, proxy_worker *worker, } } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE2, 0, r->server, "proxy: CONNECT: finished with poll() - cleaning up"); /* diff --git a/modules/proxy/mod_proxy_fcgi.c b/modules/proxy/mod_proxy_fcgi.c index d623f69a42..3fad127e68 100644 --- a/modules/proxy/mod_proxy_fcgi.c +++ b/modules/proxy/mod_proxy_fcgi.c @@ -86,7 +86,7 @@ static int proxy_fcgi_canon(request_rec *r, char *url) return DECLINED; } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, r->server, "proxy: FCGI: canonicalising URL %s", url); err = ap_proxy_canon_netloc(r->pool, &url, NULL, NULL, &host, &port); diff --git a/modules/proxy/mod_proxy_ftp.c b/modules/proxy/mod_proxy_ftp.c index d88b7bc89f..e7b50f476b 100644 --- a/modules/proxy/mod_proxy_ftp.c +++ b/modules/proxy/mod_proxy_ftp.c @@ -228,7 +228,7 @@ static int proxy_ftp_canon(request_rec *r, char *url) } def_port = apr_uri_port_of_scheme("ftp"); - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, r->server, "proxy: FTP: canonicalising URL %s", url); port = def_port; @@ -747,7 +747,7 @@ proxy_ftp_command(const char *cmd, request_rec *r, conn_rec *ftp_ctrl, *crlf = '\0'; if (strncmp(message,"PASS ", 5) == 0) strcpy(&message[5], "****"); - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE2, 0, r->server, "proxy:>FTP: %s", message); } @@ -757,7 +757,7 @@ proxy_ftp_command(const char *cmd, request_rec *r, conn_rec *ftp_ctrl, if ((crlf = strchr(message, '\r')) != NULL || (crlf = strchr(message, '\n')) != NULL) *crlf = '\0'; - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE2, 0, r->server, "proxy:server, + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, r->server, "proxy: FTP: declining URL %s - proxyhost %s specified:", url, proxyhost); return DECLINED; /* proxy connections are via HTTP */ } if (strncasecmp(url, "ftp:", 4)) { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, r->server, "proxy: FTP: declining URL %s - not ftp:", url); return DECLINED; /* only interested in FTP */ } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, r->server, "proxy: FTP: serving URL %s", url); @@ -1123,7 +1123,7 @@ static int proxy_ftp_handler(request_rec *r, proxy_worker *worker, origin = backend->connection; sock = backend->sock; - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, r->server, "proxy: FTP: control connection complete"); @@ -1339,8 +1339,8 @@ static int proxy_ftp_handler(request_rec *r, proxy_worker *worker, if (data_port) { apr_sockaddr_t *epsv_addr; - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, - "proxy: FTP: EPSV contacting remote host on port %d", + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, r->server, + "proxy: FTP: EPSV contacting remote host on port %d", data_port); if ((rv = apr_socket_create(&data_sock, connect_addr->family, SOCK_STREAM, 0, r->pool)) != APR_SUCCESS) { @@ -1606,8 +1606,8 @@ static int proxy_ftp_handler(request_rec *r, proxy_worker *worker, size = ftpmessage; /* already pstrdup'ed: no copy necessary */ } else if (rc == 550) { /* Not a regular file */ - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, - "proxy: FTP: SIZE shows this is a directory"); + ap_log_error(APLOG_MARK, APLOG_TRACE4, 0, r->server, + "proxy: FTP: SIZE shows this is a directory"); dirlisting = 1; rc = proxy_ftp_command(apr_pstrcat(p, "CWD ", ftp_escape_globbingchars(p, path, fdconf), CRLF, NULL), @@ -1739,7 +1739,7 @@ static int proxy_ftp_handler(request_rec *r, proxy_worker *worker, "Error reading from remote server"); } if (rc == 550) { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE4, 0, r->server, "proxy: FTP: RETR failed, trying LIST instead"); /* Directory Listings should always be fetched in ASCII mode */ @@ -1806,13 +1806,13 @@ static int proxy_ftp_handler(request_rec *r, proxy_worker *worker, if (xfer_type != 'A' && size != NULL) { /* We "trust" the ftp server to really serve (size) bytes... */ apr_table_setn(r->headers_out, "Content-Length", size); - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, r->server, "proxy: FTP: Content-Length set to %s", size); } } if (r->content_type) { apr_table_setn(r->headers_out, "Content-Type", r->content_type); - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, r->server, "proxy: FTP: Content-Type set to %s", r->content_type); } @@ -1821,8 +1821,8 @@ static int proxy_ftp_handler(request_rec *r, proxy_worker *worker, char datestr[APR_RFC822_DATE_LEN]; apr_rfc822_date(datestr, mtime); apr_table_set(r->headers_out, "Last-Modified", datestr); - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, - "proxy: FTP: Last-Modified set to %s", datestr); + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, r->server, + "proxy: FTP: Last-Modified set to %s", datestr); } #endif /* USE_MDTM */ @@ -1835,8 +1835,9 @@ static int proxy_ftp_handler(request_rec *r, proxy_worker *worker, /* set content-encoding (not for dir listings, they are uncompressed)*/ if (r->content_encoding != NULL && r->content_encoding[0] != '\0') { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, - "proxy: FTP: Content-Encoding set to %s", r->content_encoding); + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, r->server, + "proxy: FTP: Content-Encoding set to %s", + r->content_encoding); apr_table_setn(r->headers_out, "Content-Encoding", r->content_encoding); } @@ -1908,7 +1909,7 @@ static int proxy_ftp_handler(request_rec *r, proxy_worker *worker, apr_bucket *e; int finish = FALSE; - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, r->server, "proxy: FTP: start body send"); /* read the body, pass it to the output filters */ @@ -1971,7 +1972,7 @@ static int proxy_ftp_handler(request_rec *r, proxy_worker *worker, break; } } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, r->server, "proxy: FTP: end body send"); } diff --git a/modules/proxy/mod_proxy_http.c b/modules/proxy/mod_proxy_http.c index 2bd0829821..84f3836601 100644 --- a/modules/proxy/mod_proxy_http.c +++ b/modules/proxy/mod_proxy_http.c @@ -53,8 +53,8 @@ static int proxy_http_canon(request_rec *r, char *url) } def_port = apr_uri_port_of_scheme(scheme); - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, - "proxy: HTTP: canonicalising URL %s", url); + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, r->server, + "proxy: HTTP: canonicalising URL %s", url); /* do syntatic check. * We break the URL into host, port, path, search @@ -1224,7 +1224,10 @@ static void ap_proxy_read_headers(request_rec *r, request_rec *rr, * Read header lines until we get the empty separator line, a read error, * the connection closes (EOF), or we timeout. */ + ap_log_rerror(APLOG_MARK, APLOG_TRACE4, 0, r, + "Headers received from backend:"); while ((len = ap_getline(buffer, size, rr, 1)) > 0) { + ap_log_rerror(APLOG_MARK, APLOG_TRACE4, 0, r, "%s", buffer); if (!(value = strchr(buffer, ':'))) { /* Find the colon separator */ @@ -1505,6 +1508,9 @@ apr_status_t ap_proxy_http_process_response(apr_pool_t * p, request_rec *r, r->status = proxy_status; r->status_line = proxy_status_line; + ap_log_rerror(APLOG_MARK, APLOG_TRACE3, 0, r, + "Status from backend: %d", proxy_status); + /* read the headers. */ /* N.B. for HTTP/1.0 clients, we have to fold line-wrapped headers*/ /* Also, take care with headers with multiple occurences. */ @@ -1652,7 +1658,7 @@ apr_status_t ap_proxy_http_process_response(apr_pool_t * p, request_rec *r, */ const char *policy = apr_table_get(r->subprocess_env, "proxy-interim-response"); - ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, + ap_log_rerror(APLOG_MARK, APLOG_TRACE2, 0, r, "proxy: HTTP: received interim %d response", r->status); if (!policy || !strcasecmp(policy, "RFC")) { @@ -1745,7 +1751,7 @@ apr_status_t ap_proxy_http_process_response(apr_pool_t * p, request_rec *r, apr_table_unset(r->headers_out,"Transfer-Encoding"); - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, r->server, "proxy: start body send"); /* @@ -1849,11 +1855,11 @@ apr_status_t ap_proxy_http_process_response(apr_pool_t * p, request_rec *r, } while (!finish); } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE2, 0, r->server, "proxy: end body send"); } else if (!interim_response) { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE2, 0, r->server, "proxy: header only"); /* Pass EOS bucket down the filter chain. */ @@ -1953,8 +1959,8 @@ static int proxy_http_handler(request_rec *r, proxy_worker *worker, else proxy_function = "FTP"; } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, - "proxy: HTTP: serving URL %s", url); + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, r->server, + "proxy: HTTP: serving URL %s", url); /* create space for state information */ diff --git a/modules/proxy/proxy_util.c b/modules/proxy/proxy_util.c index 59635f9674..570b4cc090 100644 --- a/modules/proxy/proxy_util.c +++ b/modules/proxy/proxy_util.c @@ -915,7 +915,7 @@ PROXY_DECLARE(int) ap_proxy_checkproxyblock(request_rec *r, proxy_server_conf *c struct noproxy_entry *npent = (struct noproxy_entry *) conf->noproxies->elts; struct apr_sockaddr_t *conf_addr = npent[j].addr; uri_addr = src_uri_addr; - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE2, 0, r->server, "proxy: checking remote machine [%s] against [%s]", uri_addr->hostname, npent[j].name); if ((npent[j].name && ap_strstr_c(uri_addr->hostname, npent[j].name)) || npent[j].name[0] == '*') { @@ -930,7 +930,7 @@ PROXY_DECLARE(int) ap_proxy_checkproxyblock(request_rec *r, proxy_server_conf *c char *uri_ip; apr_sockaddr_ip_get(&conf_ip, conf_addr); apr_sockaddr_ip_get(&uri_ip, uri_addr); - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server, + ap_log_error(APLOG_MARK, APLOG_TRACE2, 0, r->server, "proxy: ProxyBlock comparing %s and %s", conf_ip, uri_ip); if (!apr_strnatcasecmp(conf_ip, uri_ip)) { ap_log_error(APLOG_MARK, APLOG_WARNING, 0, r->server, @@ -1519,18 +1519,18 @@ PROXY_DECLARE(int) ap_proxy_pre_request(proxy_worker **worker, if (access_status == DECLINED && *balancer == NULL) { *worker = ap_proxy_get_worker(r->pool, conf, *url); if (*worker) { - ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, + ap_log_rerror(APLOG_MARK, APLOG_TRACE2, 0, r, "proxy: %s: found worker %s for %s", - (*worker)->scheme, (*worker)->name, *url); + (*worker)->scheme, (*worker)->name, *url); *balancer = NULL; access_status = OK; } else if (r->proxyreq == PROXYREQ_PROXY) { if (conf->forward) { - ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, + ap_log_rerror(APLOG_MARK, APLOG_TRACE2, 0, r, "proxy: *: found forward proxy worker for %s", - *url); + *url); *balancer = NULL; *worker = conf->forward; access_status = OK; @@ -1538,7 +1538,7 @@ PROXY_DECLARE(int) ap_proxy_pre_request(proxy_worker **worker, } else if (r->proxyreq == PROXYREQ_REVERSE) { if (conf->reverse) { - ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, + ap_log_rerror(APLOG_MARK, APLOG_TRACE2, 0, r, "proxy: *: found reverse proxy worker for %s", *url); *balancer = NULL; @@ -1627,7 +1627,7 @@ PROXY_DECLARE(int) ap_proxy_connect_to_backend(apr_socket_t **newsock, apr_socket_timeout_set(*newsock, r->server->timeout); } - ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, + ap_log_rerror(APLOG_MARK, APLOG_TRACE2, 0, r, "proxy: %s: fam %d socket created to connect to %s", proxy_function, backend_addr->family, backend_name); @@ -1733,7 +1733,7 @@ PROXY_DECLARE(apr_status_t) ap_proxy_ssl_connection_cleanup(proxy_conn_rec *conn apr_off_t len; rv = apr_brigade_length(bb, 0, &len); - ap_log_rerror(APLOG_MARK, APLOG_DEBUG, rv, r, + ap_log_rerror(APLOG_MARK, APLOG_TRACE3, rv, r, "proxy: SSL cleanup brigade contained %" APR_OFF_T_FMT " bytes of data.", len); } @@ -1809,9 +1809,9 @@ PROXY_DECLARE(void) ap_proxy_initialize_worker_share(proxy_server_conf *conf, if (PROXY_WORKER_IS_INITIALIZED(worker)) { /* The worker share is already initialized */ - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, - "proxy: worker %s already initialized", - worker->name); + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, s, + "proxy: worker %s already initialized", + worker->name); return; } if (!worker->s) { @@ -1824,14 +1824,14 @@ PROXY_DECLARE(void) ap_proxy_initialize_worker_share(proxy_server_conf *conf, worker->id, getpid(), worker->name); } else { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, s, "proxy: grabbed scoreboard slot %d in child %" APR_PID_T_FMT " for worker %s", worker->id, getpid(), worker->name); } } if (!score) { score = (proxy_worker_stat *) apr_pcalloc(conf->pool, sizeof(proxy_worker_stat)); - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, s, "proxy: initialized plain memory in child %" APR_PID_T_FMT " for worker %s", getpid(), worker->name); } @@ -1842,9 +1842,9 @@ PROXY_DECLARE(void) ap_proxy_initialize_worker_share(proxy_server_conf *conf, */ if (PROXY_WORKER_IS_INITIALIZED(worker)) { /* The worker share is already initialized */ - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, - "proxy: worker %s already initialized", - worker->name); + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, s, + "proxy: worker %s already initialized", + worker->name); return; } } @@ -2466,7 +2466,7 @@ PROXY_DECLARE(int) ap_proxy_connect_backend(const char *proxy_function, " Keepalive"); } } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, + ap_log_error(APLOG_MARK, APLOG_TRACE2, 0, s, "proxy: %s: fam %d socket created to connect to %s", proxy_function, backend_addr->family, worker->hostname); diff --git a/modules/ssl/ssl_engine_init.c b/modules/ssl/ssl_engine_init.c index 34ea6f47a2..a2ba9a1331 100644 --- a/modules/ssl/ssl_engine_init.c +++ b/modules/ssl/ssl_engine_init.c @@ -141,7 +141,7 @@ static int ssl_tmp_key_init_dh(server_rec *s, static int ssl_tmp_keys_init(server_rec *s) { - ap_log_error(APLOG_MARK, APLOG_INFO, 0, s, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, s, "Init: Generating temporary RSA private keys (512/1024 bits)"); if (MODSSL_TMP_KEY_INIT_RSA(s, 512) || @@ -149,7 +149,7 @@ static int ssl_tmp_keys_init(server_rec *s) return !OK; } - ap_log_error(APLOG_MARK, APLOG_INFO, 0, s, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, s, "Init: Generating temporary DH parameters (512/1024 bits)"); if (MODSSL_TMP_KEY_INIT_DH(s, 512) || @@ -482,7 +482,7 @@ static void ssl_init_ctx_protocol(server_rec *s, NULL); cp[strlen(cp)-2] = NUL; - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, s, "Creating new SSL context (protocols: %s)", cp); if (protocol == SSL_PROTOCOL_SSLV2) { @@ -621,7 +621,7 @@ static void ssl_init_ctx_verify(server_rec *s, * Configure Client Authentication details */ if (mctx->auth.ca_cert_file || mctx->auth.ca_cert_path) { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, s, "Configuring client authentication"); if (!SSL_CTX_load_verify_locations(ctx, @@ -684,7 +684,7 @@ static void ssl_init_ctx_cipher_suite(server_rec *s, return; } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, s, "Configuring permitted SSL ciphers [%s]", suite); diff --git a/modules/ssl/ssl_engine_io.c b/modules/ssl/ssl_engine_io.c index b641f77bee..762a03b569 100644 --- a/modules/ssl/ssl_engine_io.c +++ b/modules/ssl/ssl_engine_io.c @@ -941,6 +941,7 @@ static void ssl_filter_io_shutdown(ssl_filter_ctx_t *filter_ctx, const char *type = ""; SSLConnRec *sslconn = myConnConfig(c); int shutdown_type; + int loglevel = APLOG_DEBUG; if (!ssl) { return; @@ -985,6 +986,7 @@ static void ssl_filter_io_shutdown(ssl_filter_ctx_t *filter_ctx, if (abortive) { shutdown_type = SSL_SENT_SHUTDOWN|SSL_RECEIVED_SHUTDOWN; type = "abortive"; + loglevel = APLOG_INFO; } else switch (sslconn->shutdown_type) { case SSL_SHUTDOWN_TYPE_UNCLEAN: @@ -1015,8 +1017,8 @@ static void ssl_filter_io_shutdown(ssl_filter_ctx_t *filter_ctx, SSL_smart_shutdown(ssl); /* and finally log the fact that we've closed the connection */ - if (APLOGcinfo(c)) { - ap_log_cerror(APLOG_MARK, APLOG_INFO, 0, c, + if (APLOG_C_IS_LEVEL(c, loglevel)) { + ap_log_cerror(APLOG_MARK, loglevel, 0, c, "Connection closed to child %ld with %s shutdown " "(server %s)", c->id, type, ssl_util_vhostid(c->pool, mySrvFromConn(c))); @@ -1168,7 +1170,7 @@ static apr_status_t ssl_io_filter_handshake(ssl_filter_ctx_t *filter_ctx) return MODSSL_ERROR_HTTP_ON_HTTPS; } else if (ssl_err == SSL_ERROR_SYSCALL) { - ap_log_cerror(APLOG_MARK, APLOG_INFO, rc, c, + ap_log_cerror(APLOG_MARK, APLOG_DEBUG, rc, c, "SSL handshake interrupted by system " "[Hint: Stop button pressed in browser?!]"); } @@ -1502,7 +1504,7 @@ int ssl_io_buffer_fill(request_rec *r, apr_size_t maxlen) /* ... and a temporary brigade. */ tempb = apr_brigade_create(r->pool, c->bucket_alloc); - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, c, "filling buffer, max size " + ap_log_cerror(APLOG_MARK, APLOG_TRACE4, 0, c, "filling buffer, max size " "%" APR_SIZE_T_FMT " bytes", maxlen); do { @@ -1554,7 +1556,7 @@ int ssl_io_buffer_fill(request_rec *r, apr_size_t maxlen) APR_BRIGADE_INSERT_TAIL(ctx->bb, e); } - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE4, 0, c, "total of %" APR_OFF_T_FMT " bytes in buffer, eos=%d", total, eos); @@ -1598,7 +1600,7 @@ static apr_status_t ssl_io_filter_buffer(ap_filter_t *f, struct modssl_buffer_ctx *ctx = f->ctx; apr_status_t rv; - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, f->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE4, 0, f->c, "read from buffered SSL brigade, mode %d, " "%" APR_OFF_T_FMT " bytes", mode, bytes); @@ -1673,7 +1675,7 @@ static apr_status_t ssl_io_filter_buffer(ap_filter_t *f, APR_BRIGADE_INSERT_TAIL(bb, e); } - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, f->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE4, 0, f->c, "buffered SSL brigade exhausted"); /* Note that the filter must *not* be removed here; it may be * invoked again, see comment above. */ diff --git a/modules/ssl/ssl_engine_kernel.c b/modules/ssl/ssl_engine_kernel.c index e0352ab2e5..0a875d5f96 100644 --- a/modules/ssl/ssl_engine_kernel.c +++ b/modules/ssl/ssl_engine_kernel.c @@ -232,7 +232,7 @@ int ssl_hook_ReadReq(request_rec *r) * Log information about incoming HTTPS requests */ if (APLOGrinfo(r) && ap_is_initial_req(r)) { - ap_log_rerror(APLOG_MARK, APLOG_INFO, 0, r, + ap_log_rerror(APLOG_MARK, APLOG_DEBUG, 0, r, "%s HTTPS request received for child %ld (server %s)", (r->connection->keepalives <= 0 ? "Initial (No.1)" : @@ -1251,7 +1251,7 @@ RSA *ssl_callback_TmpRSA(SSL *ssl, int export, int keylen) SSLModConfigRec *mc = myModConfigFromConn(c); int idx; - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, c, "handing out temporary %d bit RSA key", keylen); /* doesn't matter if export flag is on, @@ -1283,7 +1283,7 @@ DH *ssl_callback_TmpDH(SSL *ssl, int export, int keylen) SSLModConfigRec *mc = myModConfigFromConn(c); int idx; - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, c, "handing out temporary %d bit DH key", keylen); switch (keylen) { @@ -1309,7 +1309,7 @@ EC_KEY *ssl_callback_TmpECDH(SSL *ssl, int export, int keylen) static init = 0; /* XXX Uses 256-bit key for now. TODO: support other sizes. */ - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, c, "handing out temporary 256 bit ECC key"); if (init == 0) { @@ -1541,7 +1541,7 @@ int ssl_callback_SSLVerify_CRL(int ok, X509_STORE_CTX *ctx, conn_rec *c) * Log information about CRL * (A little bit complicated because of ASN.1 and BIOs...) */ - if (APLOGdebug(s)) { + if (APLOGtrace1(s)) { char buff[512]; /* should be plenty */ BIO *bio = BIO_new(BIO_s_mem()); @@ -1559,7 +1559,7 @@ int ssl_callback_SSLVerify_CRL(int ok, X509_STORE_CTX *ctx, conn_rec *c) BIO_free(bio); - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, "%s", buff); + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, s, "%s", buff); } /* @@ -1775,7 +1775,7 @@ static void ssl_session_log(server_rec *s, "timeout=%lds ", (timeout - time(NULL))); } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, + ap_log_error(APLOG_MARK, APLOG_TRACE2, 0, s, "Inter-Process Session Cache: " "request=%s status=%s id=%s %s(session %s)", request, status, @@ -1911,46 +1911,46 @@ static void log_tracing_state(MODSSL_INFO_CB_ARG_TYPE ssl, conn_rec *c, * create the various trace messages */ if (where & SSL_CB_HANDSHAKE_START) { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, - "%s: Handshake: start", SSL_LIBRARY_NAME); + ap_log_cerror(APLOG_MARK, APLOG_TRACE3, 0, c, + "%s: Handshake: start", SSL_LIBRARY_NAME); } else if (where & SSL_CB_HANDSHAKE_DONE) { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, - "%s: Handshake: done", SSL_LIBRARY_NAME); + ap_log_cerror(APLOG_MARK, APLOG_TRACE3, 0, c, + "%s: Handshake: done", SSL_LIBRARY_NAME); } else if (where & SSL_CB_LOOP) { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, - "%s: Loop: %s", - SSL_LIBRARY_NAME, SSL_state_string_long(ssl)); + ap_log_cerror(APLOG_MARK, APLOG_TRACE3, 0, c, + "%s: Loop: %s", + SSL_LIBRARY_NAME, SSL_state_string_long(ssl)); } else if (where & SSL_CB_READ) { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, - "%s: Read: %s", - SSL_LIBRARY_NAME, SSL_state_string_long(ssl)); + ap_log_cerror(APLOG_MARK, APLOG_TRACE3, 0, c, + "%s: Read: %s", + SSL_LIBRARY_NAME, SSL_state_string_long(ssl)); } else if (where & SSL_CB_WRITE) { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, - "%s: Write: %s", - SSL_LIBRARY_NAME, SSL_state_string_long(ssl)); + ap_log_cerror(APLOG_MARK, APLOG_TRACE3, 0, c, + "%s: Write: %s", + SSL_LIBRARY_NAME, SSL_state_string_long(ssl)); } else if (where & SSL_CB_ALERT) { char *str = (where & SSL_CB_READ) ? "read" : "write"; - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, - "%s: Alert: %s:%s:%s", - SSL_LIBRARY_NAME, str, - SSL_alert_type_string_long(rc), - SSL_alert_desc_string_long(rc)); + ap_log_cerror(APLOG_MARK, APLOG_TRACE3, 0, c, + "%s: Alert: %s:%s:%s", + SSL_LIBRARY_NAME, str, + SSL_alert_type_string_long(rc), + SSL_alert_desc_string_long(rc)); } else if (where & SSL_CB_EXIT) { if (rc == 0) { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, - "%s: Exit: failed in %s", - SSL_LIBRARY_NAME, SSL_state_string_long(ssl)); + ap_log_cerror(APLOG_MARK, APLOG_TRACE3, 0, c, + "%s: Exit: failed in %s", + SSL_LIBRARY_NAME, SSL_state_string_long(ssl)); } else if (rc < 0) { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, - "%s: Exit: error in %s", - SSL_LIBRARY_NAME, SSL_state_string_long(ssl)); + ap_log_cerror(APLOG_MARK, APLOG_TRACE3, 0, c, + "%s: Exit: error in %s", + SSL_LIBRARY_NAME, SSL_state_string_long(ssl)); } } @@ -1960,14 +1960,14 @@ static void log_tracing_state(MODSSL_INFO_CB_ARG_TYPE ssl, conn_rec *c, * right after a finished handshake. */ if (where & SSL_CB_HANDSHAKE_DONE) { - ap_log_error(APLOG_MARK, APLOG_INFO, 0, s, - "Connection: Client IP: %s, Protocol: %s, " - "Cipher: %s (%s/%s bits)", - ssl_var_lookup(NULL, s, c, NULL, "REMOTE_ADDR"), - ssl_var_lookup(NULL, s, c, NULL, "SSL_PROTOCOL"), - ssl_var_lookup(NULL, s, c, NULL, "SSL_CIPHER"), - ssl_var_lookup(NULL, s, c, NULL, "SSL_CIPHER_USEKEYSIZE"), - ssl_var_lookup(NULL, s, c, NULL, "SSL_CIPHER_ALGKEYSIZE")); + ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, c, + "Connection: Client IP: %s, Protocol: %s, " + "Cipher: %s (%s/%s bits)", + ssl_var_lookup(NULL, s, c, NULL, "REMOTE_ADDR"), + ssl_var_lookup(NULL, s, c, NULL, "SSL_PROTOCOL"), + ssl_var_lookup(NULL, s, c, NULL, "SSL_CIPHER"), + ssl_var_lookup(NULL, s, c, NULL, "SSL_CIPHER_USEKEYSIZE"), + ssl_var_lookup(NULL, s, c, NULL, "SSL_CIPHER_ALGKEYSIZE")); } } diff --git a/modules/ssl/ssl_engine_rand.c b/modules/ssl/ssl_engine_rand.c index a3c0fc5b7d..a4b7ca50bd 100644 --- a/modules/ssl/ssl_engine_rand.c +++ b/modules/ssl/ssl_engine_rand.c @@ -124,7 +124,7 @@ int ssl_rand_seed(server_rec *s, apr_pool_t *p, ssl_rsctx_t nCtx, char *prefix) } } } - ap_log_error(APLOG_MARK, APLOG_INFO, 0, s, + ap_log_error(APLOG_MARK, APLOG_TRACE2, 0, s, "%sSeeding PRNG with %d bytes of entropy", prefix, nDone); if (RAND_status() == 0) diff --git a/server/protocol.c b/server/protocol.c index 2379d580ab..4a5cce27e8 100644 --- a/server/protocol.c +++ b/server/protocol.c @@ -623,6 +623,12 @@ static int read_request_line(request_rec *r, apr_bucket_brigade *bb) } } while ((len <= 0) && (++num_blank_lines < max_blank_lines)); + if (APLOGrtrace5(r)) { + ap_log_rerror(APLOG_MARK, APLOG_TRACE5, 0, r, + "Request received from client: %s", + ap_escape_logitem(r->pool, r->the_request)); + } + /* we've probably got something to do, ignore graceful restart requests */ r->request_time = apr_time_now(); -- 2.50.1