From: Stefan Eissing Date: Mon, 21 Dec 2015 16:02:32 +0000 (+0000) Subject: cleanup of DEBUG log level to who all frame types receveid and sent X-Git-Tag: 2.5.0-alpha~2507 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=b5bc0852812b87d3527583a076387f86c0d0f665;p=thirdparty%2Fapache%2Fhttpd.git cleanup of DEBUG log level to who all frame types receveid and sent git-svn-id: https://svn.apache.org/repos/asf/httpd/httpd/trunk@1721204 13f79535-47bb-0310-9956-ffa450edef68 --- diff --git a/modules/http2/h2_conn.c b/modules/http2/h2_conn.c index c7c249cf907..b2f2127c1d3 100644 --- a/modules/http2/h2_conn.c +++ b/modules/http2/h2_conn.c @@ -95,7 +95,7 @@ apr_status_t h2_conn_child_init(apr_pool_t *pool, server_rec *s) maxw = minw; } - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, s, "h2_workers: min=%d max=%d, mthrpchild=%d", minw, maxw, max_threads_per_child); diff --git a/modules/http2/h2_from_h1.c b/modules/http2/h2_from_h1.c index e4264dc4093..d6170c243ba 100644 --- a/modules/http2/h2_from_h1.c +++ b/modules/http2/h2_from_h1.c @@ -507,7 +507,7 @@ apr_status_t h2_response_output_filter(ap_filter_t *f, apr_bucket_brigade *bb) */ if (AP_BUCKET_IS_EOC(b)) { ap_remove_output_filter(f); - ap_log_cerror(APLOG_MARK, APLOG_INFO, 0, f->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, f->c, "h2_from_h1(%d): eoc bucket passed", from_h1->stream_id); return ap_pass_brigade(f->next, bb); @@ -526,7 +526,7 @@ apr_status_t h2_response_output_filter(ap_filter_t *f, apr_bucket_brigade *bb) from_h1->response = create_response(from_h1, r); if (from_h1->response == NULL) { - ap_log_cerror(APLOG_MARK, APLOG_INFO, 0, f->c, + ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, f->c, "h2_from_h1(%d): unable to create response", from_h1->stream_id); return APR_ENOMEM; diff --git a/modules/http2/h2_h2.c b/modules/http2/h2_h2.c index 95bb922f37e..49fab8a7b97 100644 --- a/modules/http2/h2_h2.c +++ b/modules/http2/h2_h2.c @@ -449,7 +449,7 @@ static int h2_h2_post_read_req(request_rec *r); apr_status_t h2_h2_init(apr_pool_t *pool, server_rec *s) { (void)pool; - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, "h2_h2, child_init"); + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, s, "h2_h2, child_init"); opt_ssl_engine_disable = APR_RETRIEVE_OPTIONAL_FN(ssl_engine_disable); opt_ssl_is_https = APR_RETRIEVE_OPTIONAL_FN(ssl_is_https); opt_ssl_var_lookup = APR_RETRIEVE_OPTIONAL_FN(ssl_var_lookup); diff --git a/modules/http2/h2_mplx.c b/modules/http2/h2_mplx.c index c0cdbb67a93..bdcc2b5e443 100644 --- a/modules/http2/h2_mplx.c +++ b/modules/http2/h2_mplx.c @@ -74,7 +74,7 @@ static void have_out_data_for(h2_mplx *m, int stream_id); static void h2_mplx_destroy(h2_mplx *m) { AP_DEBUG_ASSERT(m); - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, m->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, m->c, "h2_mplx(%ld): destroy, refs=%d", m->id, m->refs); m->aborted = 1; @@ -273,12 +273,12 @@ apr_status_t h2_mplx_release_and_join(h2_mplx *m, apr_thread_cond_t *wait) release(m, 0); while (m->refs > 0) { m->join_wait = wait; - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, m->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, m->c, "h2_mplx(%ld): release_join, refs=%d, waiting...", m->id, m->refs); apr_thread_cond_wait(wait, m->lock); } - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, m->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, m->c, "h2_mplx(%ld): release_join -> destroy, (#ios=%ld)", m->id, (long)h2_io_set_size(m->stream_ios)); apr_thread_mutex_unlock(m->lock); @@ -569,7 +569,7 @@ h2_stream *h2_mplx_next_submit(h2_mplx *m, h2_stream_set *streams) * reset by the client. Should no longer happen since such * streams should clear io's from the ready queue. */ - ap_log_cerror(APLOG_MARK, APLOG_INFO, 0, m->c, APLOGNO(02953) + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, m->c, "h2_mplx(%ld): stream for response %d closed, " "resetting io to close request processing", m->id, io->id); @@ -700,7 +700,7 @@ apr_status_t h2_mplx_out_write(h2_mplx *m, int stream_id, h2_io *io = h2_io_set_get(m->stream_ios, stream_id); if (io && !io->orphaned) { status = out_write(m, io, f, bb, trailers, iowait); - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, m->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, status, m->c, "h2_mplx(%ld-%d): write with trailers=%s", m->id, io->id, trailers? "yes" : "no"); H2_MPLX_IO_OUT(APLOG_TRACE2, m, io, "h2_mplx_out_write"); @@ -742,11 +742,11 @@ apr_status_t h2_mplx_out_close(h2_mplx *m, int stream_id, apr_table_t *trailers) h2_response *r = h2_response_die(stream_id, APR_EGENERAL, io->request, m->pool); status = out_open(m, stream_id, r, NULL, NULL, NULL); - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, m->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, status, m->c, "h2_mplx(%ld-%d): close, no response, no rst", m->id, io->id); } - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, m->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, status, m->c, "h2_mplx(%ld-%d): close with trailers=%s", m->id, io->id, trailers? "yes" : "no"); status = h2_io_out_close(io, trailers); diff --git a/modules/http2/h2_session.c b/modules/http2/h2_session.c index 2f19afab535..fbe4cf7fbb6 100644 --- a/modules/http2/h2_session.c +++ b/modules/http2/h2_session.c @@ -62,7 +62,7 @@ static void update_window(void *ctx, int stream_id, apr_off_t bytes_read) { h2_session *session = (h2_session*)ctx; nghttp2_session_consume(session->ngh2, stream_id, bytes_read); - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, session->c, "h2_session(%ld-%d): consumed %ld bytes", session->id, stream_id, (long)bytes_read); } @@ -238,7 +238,7 @@ static int on_data_chunk_recv_cb(nghttp2_session *ngh2, uint8_t flags, stream = h2_session_get_stream(session, stream_id); if (!stream) { ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, - "h2_session: stream(%ld-%d): on_data_chunk for unknown stream", + "h2_stream(%ld-%d): on_data_chunk for unknown stream", session->id, (int)stream_id); rv = nghttp2_submit_rst_stream(ngh2, NGHTTP2_FLAG_NONE, stream_id, NGHTTP2_INTERNAL_ERROR); @@ -268,7 +268,7 @@ static apr_status_t stream_release(h2_session *session, uint32_t error_code) { if (!error_code) { - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, session->c, "h2_stream(%ld-%d): handled, closing", session->id, (int)stream->id); if (stream->id > session->max_stream_handled) { @@ -375,10 +375,15 @@ static int on_frame_recv_cb(nghttp2_session *ng2s, return NGHTTP2_ERR_CALLBACK_FAILURE; } - ap_log_cerror(APLOG_MARK, APLOG_TRACE2, 0, session->c, - "h2_stream(%ld-%d): on_frame_rcv #%ld, type=%d", - session->id, frame->hd.stream_id, - (long)session->frames_received, frame->hd.type); + if (APLOGcdebug(session->c)) { + char buffer[256]; + + frame_print(frame, buffer, sizeof(buffer)/sizeof(buffer[0])); + ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, + "h2_session(%ld): recv FRAME[%s], frames=%ld/%ld (r/s)", + session->id, buffer, (long)session->frames_received, + (long)session->frames_sent); + } ++session->frames_received; switch (frame->hd.type) { @@ -600,7 +605,7 @@ static int on_frame_send_cb(nghttp2_session *ngh2, frame_print(frame, buffer, sizeof(buffer)/sizeof(buffer[0])); ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, - "h2_session(%ld): send %s, frames=%ld/%ld (r/s)", + "h2_session(%ld): sent FRAME[%s], frames=%ld/%ld (r/s)", session->id, buffer, (long)session->frames_received, (long)session->frames_sent); } @@ -883,7 +888,7 @@ static apr_status_t h2_session_abort_int(h2_session *session, int reason) const char *err = nghttp2_strerror(reason); ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, - "session(%ld): aborting session, reason=%d %s", + "session(%ld): abort, reason=%d %s", session->id, reason, err); /* The connection might still be there and we shut down @@ -1054,8 +1059,8 @@ static int resume_on_data(void *ctx, h2_stream *stream) ap_log_cerror(APLOG_MARK, nghttp2_is_fatal(rv)? APLOG_ERR : APLOG_DEBUG, 0, session->c, APLOGNO(02936) - "h2_stream(%ld-%d): resuming stream %s", - session->id, stream->id, nghttp2_strerror(rv)); + "h2_stream(%ld-%d): resuming %s", + session->id, stream->id, rv? nghttp2_strerror(rv) : ""); } } return 1; @@ -1093,9 +1098,6 @@ apr_status_t h2_session_close(h2_session *session) if (!session->aborted) { h2_session_abort_int(session, 0); } - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0,session->c, - "h2_session: closing, writing eoc"); - h2_session_cleanup(session); return h2_conn_io_close(&session->io, session); } @@ -1157,7 +1159,7 @@ static ssize_t stream_data_cb(nghttp2_session *ng2s, nread = 0; h2_stream_set_suspended(stream, 1); ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, - "h2_stream(%ld-%d): suspending stream", + "h2_stream(%ld-%d): suspending", session->id, (int)stream_id); return NGHTTP2_ERR_DEFERRED; @@ -1321,7 +1323,7 @@ struct h2_stream *h2_session_push(h2_session *session, h2_stream *is, h2_stream_set_h2_request(stream, is->id, push->req); status = stream_schedule(session, stream, 1); if (status != APR_SUCCESS) { - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, status, session->c, "h2_stream(%ld-%d): scheduling push stream", session->id, stream->id); h2_stream_cleanup(stream); @@ -1360,7 +1362,7 @@ apr_status_t h2_session_set_prio(h2_session *session, h2_stream *stream, s = nghttp2_session_find_stream(session->ngh2, stream->id); if (!s) { - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, session->c, "h2_stream(%ld-%d): lookup of nghttp2_stream failed", session->id, stream->id); return APR_EINVAL; @@ -1410,7 +1412,7 @@ apr_status_t h2_session_set_prio(h2_session *session, h2_stream *stream, rv = nghttp2_session_change_stream_priority(session->ngh2, id_parent, &ps); if (rv < 0) { ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, session->c, - "h2_stream(%ld-%d): PUSH BEFORE2, weight=%d, " + "h2_stream(%ld-%d): PUSH BEFORE, weight=%d, " "depends=%d, returned=%d", session->id, id_parent, ps.weight, ps.stream_id, rv); return APR_EGENERAL; @@ -1546,7 +1548,7 @@ static int frame_print(const nghttp2_frame *frame, char *buffer, size_t maxlen) } default: return apr_snprintf(buffer, maxlen, - "FRAME[type=%d, length=%d, flags=%d, stream=%d]", + "type=%d[length=%d, flags=%d, stream=%d]", frame->hd.type, (int)frame->hd.length, frame->hd.flags, frame->hd.stream_id); } @@ -1564,9 +1566,9 @@ static apr_status_t h2_session_send(h2_session *session) { int rv = nghttp2_session_send(session->ngh2); if (rv != 0) { - ap_log_cerror( APLOG_MARK, APLOG_DEBUG, 0, session->c, - "h2_session: send: %s", nghttp2_strerror(rv)); if (nghttp2_is_fatal(rv)) { + ap_log_cerror( APLOG_MARK, APLOG_DEBUG, 0, session->c, + "h2_session: send gave error=%s", nghttp2_strerror(rv)); h2_session_abort_int(session, rv); return APR_EGENERAL; } @@ -1589,7 +1591,7 @@ static apr_status_t h2_session_receive(void *ctx, const char *data, if (n < 0) { ap_log_cerror(APLOG_MARK, APLOG_DEBUG, APR_EGENERAL, session->c, - "h2_session: nghttp2_session_mem_recv error %d", + "h2_session: nghttp2_session_mem_recv error=%d", (int)n); if (nghttp2_is_fatal((int)n)) { h2_session_abort(session, 0, (int)n); @@ -1638,9 +1640,10 @@ static apr_status_t h2_session_read(h2_session *session, int block, int loops) || APR_STATUS_IS_ECONNABORTED(status) || APR_STATUS_IS_ECONNRESET(status) || APR_STATUS_IS_EOF(status) + || APR_STATUS_IS_TIMEUP(status) || APR_STATUS_IS_EBADF(status)) { /* common status for a client that has left */ - ap_log_cerror( APLOG_MARK, APLOG_DEBUG, status, session->c, + ap_log_cerror( APLOG_MARK, APLOG_TRACE1, status, session->c, "h2_session(%ld): terminating", session->id); /* Stolen from mod_reqtimeout to speed up lingering when @@ -1715,7 +1718,7 @@ apr_status_t h2_session_process(h2_session *session, int async) if (session->aborted || (!nghttp2_session_want_read(session->ngh2) && !nghttp2_session_want_write(session->ngh2))) { - ap_log_cerror( APLOG_MARK, APLOG_DEBUG, status, session->c, + ap_log_cerror( APLOG_MARK, APLOG_TRACE1, status, session->c, "h2_session(%ld): process -> aborted", session->id); h2_conn_io_flush(&session->io); return APR_EOF; @@ -1731,7 +1734,7 @@ apr_status_t h2_session_process(h2_session *session, int async) status = h2_session_start(session, &rv); ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, session->c, - "h2_session(%ld): starting on %s:%d", session->id, + "h2_session(%ld): started on %s:%d", session->id, session->s->server_hostname, session->c->local_addr->port); if (status != APR_SUCCESS) { @@ -1806,7 +1809,7 @@ apr_status_t h2_session_process(h2_session *session, int async) session->id); } } - ap_log_cerror( APLOG_MARK, APLOG_DEBUG, status, session->c, + ap_log_cerror( APLOG_MARK, APLOG_TRACE1, status, session->c, "h2_session(%ld): timeout", session->id); return status; } diff --git a/modules/http2/h2_stream.c b/modules/http2/h2_stream.c index 1006bc2123e..45d4cd1422c 100644 --- a/modules/http2/h2_stream.c +++ b/modules/http2/h2_stream.c @@ -201,7 +201,7 @@ void h2_stream_rst(h2_stream *stream, int error_code) stream->rst_error = error_code; close_input(stream); close_output(stream); - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, stream->session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c, "h2_stream(%ld-%d): reset, error=%d", stream->session->id, stream->id, error_code); } @@ -211,7 +211,7 @@ apr_status_t h2_stream_set_response(h2_stream *stream, h2_response *response, { apr_status_t status = APR_SUCCESS; if (!output_open(stream)) { - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, stream->session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c, "h2_stream(%ld-%d): output closed", stream->session->id, stream->id); return APR_ECONNRESET; @@ -229,7 +229,7 @@ apr_status_t h2_stream_set_response(h2_stream *stream, h2_response *response, H2_STREAM_OUT(APLOG_TRACE2, stream, "h2_stream set_response_post"); } - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, stream->session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, status, stream->session->c, "h2_stream(%ld-%d): set_response(%d)", stream->session->id, stream->id, response->http_status); return status; @@ -307,7 +307,7 @@ apr_status_t h2_stream_schedule(h2_stream *stream, int eos, int push_enabled, stream->request, eos, cmp, ctx); stream->scheduled = 1; - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, stream->session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c, "h2_stream(%ld-%d): scheduled %s %s://%s%s", stream->session->id, stream->id, stream->request->method, stream->request->scheme, @@ -315,7 +315,7 @@ apr_status_t h2_stream_schedule(h2_stream *stream, int eos, int push_enabled, } else { h2_stream_rst(stream, H2_ERR_INTERNAL_ERROR); - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, stream->session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c, "h2_stream(%ld-%d): RST=2 (internal err) %s %s://%s%s", stream->session->id, stream->id, stream->request->method, stream->request->scheme, @@ -337,7 +337,7 @@ static apr_status_t h2_stream_input_flush(h2_stream *stream) status = h2_mplx_in_write(stream->session->mplx, stream->id, stream->bbin); if (status != APR_SUCCESS) { - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, status, stream->session->mplx->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, status, stream->session->mplx->c, "h2_stream(%ld-%d): flushing input data", stream->session->id, stream->id); } @@ -362,7 +362,7 @@ apr_status_t h2_stream_close_input(h2_stream *stream) apr_status_t status = APR_SUCCESS; AP_DEBUG_ASSERT(stream); - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, stream->session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c, "h2_stream(%ld-%d): closing input", stream->session->id, stream->id); @@ -388,14 +388,14 @@ apr_status_t h2_stream_write_data(h2_stream *stream, AP_DEBUG_ASSERT(stream); if (input_closed(stream) || !stream->request->eoh || !stream->bbin) { - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, stream->session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c, "h2_stream(%ld-%d): writing denied, closed=%d, eoh=%d, bbin=%d", stream->session->id, stream->id, input_closed(stream), stream->request->eoh, !!stream->bbin); return APR_EINVAL; } - ap_log_cerror(APLOG_MARK, APLOG_DEBUG, 0, stream->session->c, + ap_log_cerror(APLOG_MARK, APLOG_TRACE1, 0, stream->session->c, "h2_stream(%ld-%d): add %ld input bytes", stream->session->id, stream->id, (long)len); diff --git a/modules/http2/h2_switch.c b/modules/http2/h2_switch.c index 4885772bd86..62be23494f8 100644 --- a/modules/http2/h2_switch.c +++ b/modules/http2/h2_switch.c @@ -40,7 +40,7 @@ apr_status_t h2_switch_init(apr_pool_t *pool, server_rec *s) { (void)pool; - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, "h2_switch init"); + ap_log_error(APLOG_MARK, APLOG_TRACE1, 0, s, "h2_switch init"); return APR_SUCCESS; } diff --git a/modules/http2/h2_workers.c b/modules/http2/h2_workers.c index 191f5a323ef..33b96de499e 100644 --- a/modules/http2/h2_workers.c +++ b/modules/http2/h2_workers.c @@ -235,7 +235,7 @@ static apr_status_t h2_workers_start(h2_workers *workers) { apr_status_t status = apr_thread_mutex_lock(workers->lock); if (status == APR_SUCCESS) { - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, workers->s, + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, workers->s, "h2_workers: starting"); while (workers->worker_count < workers->min_size @@ -276,7 +276,7 @@ h2_workers *h2_workers_create(server_rec *s, apr_pool_t *server_pool, if (ap_thread_stacksize != 0) { apr_threadattr_stacksize_set(workers->thread_attr, ap_thread_stacksize); - ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, s, + ap_log_error(APLOG_MARK, APLOG_TRACE3, 0, s, "h2_workers: using stacksize=%ld", (long)ap_thread_stacksize); } diff --git a/modules/http2/mod_http2.c b/modules/http2/mod_http2.c index 464161f3b35..8e95e519c8f 100644 --- a/modules/http2/mod_http2.c +++ b/modules/http2/mod_http2.c @@ -136,7 +136,7 @@ static void h2_hooks(apr_pool_t *pool) { static const char *const mod_ssl[] = { "mod_ssl.c", NULL}; - ap_log_perror(APLOG_MARK, APLOG_INFO, 0, pool, "installing hooks"); + ap_log_perror(APLOG_MARK, APLOG_TRACE1, 0, pool, "installing hooks"); /* Run once after configuration is set, but before mpm children initialize. */