From 0630bb21be5bf5ff4300229ea7c0f2d626ddcb98 Mon Sep 17 00:00:00 2001 From: Daniel Stenberg Date: Tue, 30 Jan 2018 23:19:53 +0100 Subject: [PATCH] http2: set DEBUG_HTTP2 to enable more HTTP/2 logging ... instead of doing it unconditionally in debug builds. It cluttered up the output a little too much. --- lib/http2.c | 126 +++++++++++++++++++++++++++------------------------- 1 file changed, 66 insertions(+), 60 deletions(-) diff --git a/lib/http2.c b/lib/http2.c index 699287940..d79de4676 100644 --- a/lib/http2.c +++ b/lib/http2.c @@ -5,7 +5,7 @@ * | (__| |_| | _ <| |___ * \___|\___/|_| \_\_____| * - * Copyright (C) 1998 - 2017, Daniel Stenberg, , et al. + * Copyright (C) 1998 - 2018, Daniel Stenberg, , et al. * * This software is licensed as described in the file COPYING, which * you should have received as part of this distribution. The terms @@ -65,6 +65,12 @@ #define HTTP2_HUGE_WINDOW_SIZE (1 << 30) +#ifdef DEBUG_HTTP2 +#define H2BUGF(x) x +#else +#define H2BUGF(x) do { } WHILE_FALSE +#endif + /* * Curl_http2_init_state() is called when the easy handle is created and * allows for HTTP/2 specific init of state. @@ -140,13 +146,13 @@ static CURLcode http2_disconnect(struct connectdata *conn, struct http_conn *c = &conn->proto.httpc; (void)dead_connection; - DEBUGF(infof(conn->data, "HTTP/2 DISCONNECT starts now\n")); + H2BUGF(infof(conn->data, "HTTP/2 DISCONNECT starts now\n")); nghttp2_session_del(c->h2); Curl_safefree(c->inbuf); http2_stream_free(conn->data->req.protop); - DEBUGF(infof(conn->data, "HTTP/2 DISCONNECT done\n")); + H2BUGF(infof(conn->data, "HTTP/2 DISCONNECT done\n")); return CURLE_OK; } @@ -428,7 +434,7 @@ static int push_promise(struct Curl_easy *data, const nghttp2_push_promise *frame) { int rv; - DEBUGF(infof(data, "PUSH_PROMISE received, stream %u!\n", + H2BUGF(infof(data, "PUSH_PROMISE received, stream %u!\n", frame->promised_stream_id)); if(data->multi->push_cb) { struct HTTP *stream; @@ -448,7 +454,7 @@ static int push_promise(struct Curl_easy *data, heads.data = data; heads.frame = frame; /* ask the application */ - DEBUGF(infof(data, "Got PUSH_PROMISE, ask application!\n")); + H2BUGF(infof(data, "Got PUSH_PROMISE, ask application!\n")); stream = data->req.protop; if(!stream) { @@ -497,7 +503,7 @@ static int push_promise(struct Curl_easy *data, frame->promised_stream_id, newhandle); } else { - DEBUGF(infof(data, "Got PUSH_PROMISE, ignore it!\n")); + H2BUGF(infof(data, "Got PUSH_PROMISE, ignore it!\n")); rv = 1; } fail: @@ -520,16 +526,16 @@ static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame, /* stream ID zero is for connection-oriented stuff */ if(frame->hd.type == NGHTTP2_SETTINGS) { uint32_t max_conn = httpc->settings.max_concurrent_streams; - DEBUGF(infof(conn->data, "Got SETTINGS\n")); + H2BUGF(infof(conn->data, "Got SETTINGS\n")); httpc->settings.max_concurrent_streams = nghttp2_session_get_remote_settings( session, NGHTTP2_SETTINGS_MAX_CONCURRENT_STREAMS); httpc->settings.enable_push = nghttp2_session_get_remote_settings( session, NGHTTP2_SETTINGS_ENABLE_PUSH); - DEBUGF(infof(conn->data, "MAX_CONCURRENT_STREAMS == %d\n", + H2BUGF(infof(conn->data, "MAX_CONCURRENT_STREAMS == %d\n", httpc->settings.max_concurrent_streams)); - DEBUGF(infof(conn->data, "ENABLE_PUSH == %s\n", + H2BUGF(infof(conn->data, "ENABLE_PUSH == %s\n", httpc->settings.enable_push?"TRUE":"false")); if(max_conn != httpc->settings.max_concurrent_streams) { /* only signal change if the value actually changed */ @@ -545,7 +551,7 @@ static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame, lastStream = stream_id; } if(!data_s) { - DEBUGF(infof(conn->data, + H2BUGF(infof(conn->data, "No Curl_easy associated with stream: %x\n", stream_id)); return 0; @@ -553,12 +559,12 @@ static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame, stream = data_s->req.protop; if(!stream) { - DEBUGF(infof(conn->data, "No proto pointer for stream: %x\n", + H2BUGF(infof(conn->data, "No proto pointer for stream: %x\n", stream_id)); return NGHTTP2_ERR_CALLBACK_FAILURE; } - DEBUGF(infof(data_s, "on_frame_recv() header %x stream %x\n", + H2BUGF(infof(data_s, "on_frame_recv() header %x stream %x\n", frame->hd.type, stream_id)); switch(frame->hd.type) { @@ -600,7 +606,7 @@ static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame, ncopy); stream->nread_header_recvbuf += ncopy; - DEBUGF(infof(data_s, "Store %zu bytes headers from stream %u at %p\n", + H2BUGF(infof(data_s, "Store %zu bytes headers from stream %u at %p\n", ncopy, stream_id, stream->mem)); stream->len -= ncopy; @@ -629,7 +635,7 @@ static int on_frame_recv(nghttp2_session *session, const nghttp2_frame *frame, } break; default: - DEBUGF(infof(conn->data, "Got frame type %x for stream %u!\n", + H2BUGF(infof(conn->data, "Got frame type %x for stream %u!\n", frame->hd.type, stream_id)); break; } @@ -642,13 +648,13 @@ static int on_invalid_frame_recv(nghttp2_session *session, { struct Curl_easy *data_s = NULL; (void)userp; -#if !defined(DEBUGBUILD) || defined(CURL_DISABLE_VERBOSE_STRINGS) +#if !defined(DEBUG_HTTP2) || defined(CURL_DISABLE_VERBOSE_STRINGS) (void)lib_error_code; #endif data_s = nghttp2_session_get_stream_user_data(session, frame->hd.stream_id); if(data_s) { - DEBUGF(infof(data_s, + H2BUGF(infof(data_s, "on_invalid_frame_recv() was called, error=%d:%s\n", lib_error_code, nghttp2_strerror(lib_error_code))); } @@ -693,7 +699,7 @@ static int on_data_chunk_recv(nghttp2_session *session, uint8_t flags, if(conn->data != data_s) Curl_expire(data_s, 0, EXPIRE_RUN_NOW); - DEBUGF(infof(data_s, "%zu data received for stream %u " + H2BUGF(infof(data_s, "%zu data received for stream %u " "(%zu left in buffer %p, total %zu)\n", nread, stream_id, stream->len, stream->mem, @@ -702,7 +708,7 @@ static int on_data_chunk_recv(nghttp2_session *session, uint8_t flags, if(nread < len) { stream->pausedata = data + nread; stream->pauselen = len - nread; - DEBUGF(infof(data_s, "NGHTTP2_ERR_PAUSE - %zu bytes out of buffer" + H2BUGF(infof(data_s, "NGHTTP2_ERR_PAUSE - %zu bytes out of buffer" ", stream %u\n", len - nread, stream_id)); data_s->easy_conn->proto.httpc.pause_stream_id = stream_id; @@ -730,7 +736,7 @@ static int before_frame_send(nghttp2_session *session, data_s = nghttp2_session_get_stream_user_data(session, frame->hd.stream_id); if(data_s) { - DEBUGF(infof(data_s, "before_frame_send() was called\n")); + H2BUGF(infof(data_s, "before_frame_send() was called\n")); } return 0; @@ -744,7 +750,7 @@ static int on_frame_send(nghttp2_session *session, data_s = nghttp2_session_get_stream_user_data(session, frame->hd.stream_id); if(data_s) { - DEBUGF(infof(data_s, "on_frame_send() was called, length = %zd\n", + H2BUGF(infof(data_s, "on_frame_send() was called, length = %zd\n", frame->hd.length)); } return 0; @@ -755,13 +761,13 @@ static int on_frame_not_send(nghttp2_session *session, { struct Curl_easy *data_s; (void)userp; -#if !defined(DEBUGBUILD) || defined(CURL_DISABLE_VERBOSE_STRINGS) +#if !defined(DEBUG_HTTP2) || defined(CURL_DISABLE_VERBOSE_STRINGS) (void)lib_error_code; #endif data_s = nghttp2_session_get_stream_user_data(session, frame->hd.stream_id); if(data_s) { - DEBUGF(infof(data_s, + H2BUGF(infof(data_s, "on_frame_not_send() was called, lib_error_code = %d\n", lib_error_code)); } @@ -785,7 +791,7 @@ static int on_stream_close(nghttp2_session *session, int32_t stream_id, decided to reject stream (e.g., PUSH_PROMISE). */ return 0; } - DEBUGF(infof(data_s, "on_stream_close(), %s (err %d), stream %u\n", + H2BUGF(infof(data_s, "on_stream_close(), %s (err %d), stream %u\n", Curl_http2_strerror(error_code), error_code, stream_id)); stream = data_s->req.protop; if(!stream) @@ -798,7 +804,7 @@ static int on_stream_close(nghttp2_session *session, int32_t stream_id, /* remove the entry from the hash as the stream is now gone */ nghttp2_session_set_stream_user_data(session, stream_id, 0); - DEBUGF(infof(data_s, "Removed stream %u hash!\n", stream_id)); + H2BUGF(infof(data_s, "Removed stream %u hash!\n", stream_id)); } return 0; } @@ -815,7 +821,7 @@ static int on_begin_headers(nghttp2_session *session, return 0; } - DEBUGF(infof(data_s, "on_begin_headers() was called\n")); + H2BUGF(infof(data_s, "on_begin_headers() was called\n")); if(frame->hd.type != NGHTTP2_HEADERS) { return 0; @@ -827,7 +833,7 @@ static int on_begin_headers(nghttp2_session *session, } /* This is trailer HEADERS started. Allocate buffer for them. */ - DEBUGF(infof(data_s, "trailer field started\n")); + H2BUGF(infof(data_s, "trailer field started\n")); DEBUGASSERT(stream->trailer_recvbuf == NULL); @@ -928,7 +934,7 @@ static int on_header(nghttp2_session *session, const nghttp2_frame *frame, /* 4 is for ": " and "\r\n". */ uint32_t n = (uint32_t)(namelen + valuelen + 4); - DEBUGF(infof(data_s, "h2 trailer: %.*s: %.*s\n", namelen, name, valuelen, + H2BUGF(infof(data_s, "h2 trailer: %.*s: %.*s\n", namelen, name, valuelen, value)); Curl_add_buffer(stream->trailer_recvbuf, &n, sizeof(n)); @@ -956,7 +962,7 @@ static int on_header(nghttp2_session *session, const nghttp2_frame *frame, if(conn->data != data_s) Curl_expire(data_s, 0, EXPIRE_RUN_NOW); - DEBUGF(infof(data_s, "h2 status: HTTP/2 %03d (easy %p)\n", + H2BUGF(infof(data_s, "h2 status: HTTP/2 %03d (easy %p)\n", stream->status_code, data_s)); return 0; } @@ -972,7 +978,7 @@ static int on_header(nghttp2_session *session, const nghttp2_frame *frame, if(conn->data != data_s) Curl_expire(data_s, 0, EXPIRE_RUN_NOW); - DEBUGF(infof(data_s, "h2 header: %.*s: %.*s\n", namelen, name, valuelen, + H2BUGF(infof(data_s, "h2 header: %.*s: %.*s\n", namelen, name, valuelen, value)); return 0; /* 0 is successful */ @@ -1021,7 +1027,7 @@ static ssize_t data_source_read_callback(nghttp2_session *session, else if(nread == 0) return NGHTTP2_ERR_DEFERRED; - DEBUGF(infof(data_s, "data_source_read_callback: " + H2BUGF(infof(data_s, "data_source_read_callback: " "returns %zu bytes stream %u\n", nread, stream_id)); @@ -1067,7 +1073,7 @@ void Curl_http2_done(struct connectdata *conn, bool premature) struct http_conn *httpc = &conn->proto.httpc; if(http->header_recvbuf) { - DEBUGF(infof(data, "free header_recvbuf!!\n")); + H2BUGF(infof(data, "free header_recvbuf!!\n")); Curl_add_buffer_free(http->header_recvbuf); http->header_recvbuf = NULL; /* clear the pointer */ Curl_add_buffer_free(http->trailer_recvbuf); @@ -1246,7 +1252,7 @@ static int h2_process_pending_input(struct Curl_easy *data, } if(nread == rv) { - DEBUGF(infof(data, + H2BUGF(infof(data, "h2_process_pending_input: All data in connection buffer " "processed\n")); httpc->inbuflen = 0; @@ -1254,7 +1260,7 @@ static int h2_process_pending_input(struct Curl_easy *data, } else { httpc->nread_inbuf += rv; - DEBUGF(infof(data, + H2BUGF(infof(data, "h2_process_pending_input: %zu bytes left in connection " "buffer\n", httpc->inbuflen - httpc->nread_inbuf)); @@ -1267,7 +1273,7 @@ static int h2_process_pending_input(struct Curl_easy *data, } if(should_close_session(httpc)) { - DEBUGF(infof(data, + H2BUGF(infof(data, "h2_process_pending_input: nothing to do in this session\n")); *err = CURLE_HTTP2; return -1; @@ -1370,7 +1376,7 @@ static ssize_t http2_handle_stream_close(struct connectdata *conn, stream->close_handled = TRUE; - DEBUGF(infof(data, "http2_recv returns 0, http2_handle_stream_close\n")); + H2BUGF(infof(data, "http2_recv returns 0, http2_handle_stream_close\n")); return 0; } @@ -1411,7 +1417,7 @@ static int h2_session_send(struct Curl_easy *data, h2_pri_spec(data, &pri_spec); - DEBUGF(infof(data, "Queuing PRIORITY on stream %u (easy %p)\n", + H2BUGF(infof(data, "Queuing PRIORITY on stream %u (easy %p)\n", stream->stream_id, data)); rv = nghttp2_submit_priority(h2, NGHTTP2_FLAG_NONE, stream->stream_id, &pri_spec); @@ -1435,7 +1441,7 @@ static ssize_t http2_recv(struct connectdata *conn, int sockindex, (void)sockindex; /* we always do HTTP2 on sockindex 0 */ if(should_close_session(httpc)) { - DEBUGF(infof(data, + H2BUGF(infof(data, "http2_recv: nothing to do in this session\n")); *err = CURLE_HTTP2; return -1; @@ -1461,16 +1467,16 @@ static ssize_t http2_recv(struct connectdata *conn, int sockindex, ncopy); stream->nread_header_recvbuf += ncopy; - DEBUGF(infof(data, "http2_recv: Got %d bytes from header_recvbuf\n", + H2BUGF(infof(data, "http2_recv: Got %d bytes from header_recvbuf\n", (int)ncopy)); return ncopy; } - DEBUGF(infof(data, "http2_recv: easy %p (stream %u)\n", + H2BUGF(infof(data, "http2_recv: easy %p (stream %u)\n", data, stream->stream_id)); if((data->state.drain) && stream->memlen) { - DEBUGF(infof(data, "http2_recv: DRAIN %zu bytes stream %u!! (%p => %p)\n", + H2BUGF(infof(data, "http2_recv: DRAIN %zu bytes stream %u!! (%p => %p)\n", stream->memlen, stream->stream_id, stream->mem, mem)); if(mem != stream->mem) { @@ -1500,7 +1506,7 @@ static ssize_t http2_recv(struct connectdata *conn, int sockindex, infof(data, "%zu data bytes written\n", nread); if(stream->pauselen == 0) { - DEBUGF(infof(data, "Unpaused by stream %u\n", stream->stream_id)); + H2BUGF(infof(data, "Unpaused by stream %u\n", stream->stream_id)); DEBUGASSERT(httpc->pause_stream_id == stream->stream_id); httpc->pause_stream_id = 0; @@ -1519,7 +1525,7 @@ static ssize_t http2_recv(struct connectdata *conn, int sockindex, return -1; } } - DEBUGF(infof(data, "http2_recv: returns unpaused %zd bytes on stream %u\n", + H2BUGF(infof(data, "http2_recv: returns unpaused %zd bytes on stream %u\n", nread, stream->stream_id)); return nread; } @@ -1532,7 +1538,7 @@ static ssize_t http2_recv(struct connectdata *conn, int sockindex, socket is not read. But it seems that usually streams are notified with its drain property, and socket is read again quickly. */ - DEBUGF(infof(data, "stream %x is paused, pause id: %x\n", + H2BUGF(infof(data, "stream %x is paused, pause id: %x\n", stream->stream_id, httpc->pause_stream_id)); *err = CURLE_AGAIN; return -1; @@ -1566,7 +1572,7 @@ static ssize_t http2_recv(struct connectdata *conn, int sockindex, return -1; } - DEBUGF(infof(data, "nread=%zd\n", nread)); + H2BUGF(infof(data, "nread=%zd\n", nread)); httpc->inbuflen = nread; inbuf = httpc->inbuf; @@ -1575,7 +1581,7 @@ static ssize_t http2_recv(struct connectdata *conn, int sockindex, nread = httpc->inbuflen - httpc->nread_inbuf; inbuf = httpc->inbuf + httpc->nread_inbuf; - DEBUGF(infof(data, "Use data left in connection buffer, nread=%zd\n", + H2BUGF(infof(data, "Use data left in connection buffer, nread=%zd\n", nread)); } rv = nghttp2_session_mem_recv(httpc->h2, (const uint8_t *)inbuf, nread); @@ -1586,15 +1592,15 @@ static ssize_t http2_recv(struct connectdata *conn, int sockindex, *err = CURLE_RECV_ERROR; return -1; } - DEBUGF(infof(data, "nghttp2_session_mem_recv() returns %zd\n", rv)); + H2BUGF(infof(data, "nghttp2_session_mem_recv() returns %zd\n", rv)); if(nread == rv) { - DEBUGF(infof(data, "All data in connection buffer processed\n")); + H2BUGF(infof(data, "All data in connection buffer processed\n")); httpc->inbuflen = 0; httpc->nread_inbuf = 0; } else { httpc->nread_inbuf += rv; - DEBUGF(infof(data, "%zu bytes left in connection buffer\n", + H2BUGF(infof(data, "%zu bytes left in connection buffer\n", httpc->inbuflen - httpc->nread_inbuf)); } /* Always send pending frames in nghttp2 session, because @@ -1606,21 +1612,21 @@ static ssize_t http2_recv(struct connectdata *conn, int sockindex, } if(should_close_session(httpc)) { - DEBUGF(infof(data, "http2_recv: nothing to do in this session\n")); + H2BUGF(infof(data, "http2_recv: nothing to do in this session\n")); *err = CURLE_HTTP2; return -1; } } if(stream->memlen) { ssize_t retlen = stream->memlen; - DEBUGF(infof(data, "http2_recv: returns %zd for stream %u\n", + H2BUGF(infof(data, "http2_recv: returns %zd for stream %u\n", retlen, stream->stream_id)); stream->memlen = 0; if(httpc->pause_stream_id == stream->stream_id) { /* data for this stream is returned now, but this stream caused a pause already so we need it called again asap */ - DEBUGF(infof(data, "Data returned for PAUSED stream %u\n", + H2BUGF(infof(data, "Data returned for PAUSED stream %u\n", stream->stream_id)); } else if(!stream->closed) { @@ -1637,7 +1643,7 @@ static ssize_t http2_recv(struct connectdata *conn, int sockindex, return http2_handle_stream_close(conn, data, stream, err); } *err = CURLE_AGAIN; - DEBUGF(infof(data, "http2_recv returns AGAIN for stream %u\n", + H2BUGF(infof(data, "http2_recv returns AGAIN for stream %u\n", stream->stream_id)); return -1; } @@ -1739,7 +1745,7 @@ static ssize_t http2_send(struct connectdata *conn, int sockindex, (void)sockindex; - DEBUGF(infof(conn->data, "http2_send len=%zu\n", len)); + H2BUGF(infof(conn->data, "http2_send len=%zu\n", len)); if(stream->stream_id != -1) { if(stream->close_handled) { @@ -1768,7 +1774,7 @@ static ssize_t http2_send(struct connectdata *conn, int sockindex, stream->upload_len = 0; if(should_close_session(httpc)) { - DEBUGF(infof(conn->data, "http2_send: nothing to do in this session\n")); + H2BUGF(infof(conn->data, "http2_send: nothing to do in this session\n")); *err = CURLE_HTTP2; return -1; } @@ -1781,7 +1787,7 @@ static ssize_t http2_send(struct connectdata *conn, int sockindex, nghttp2_session_resume_data(h2, stream->stream_id); } - DEBUGF(infof(conn->data, "http2_send returns %zu for stream %u\n", len, + H2BUGF(infof(conn->data, "http2_send returns %zu for stream %u\n", len, stream->stream_id)); return len; } @@ -1937,7 +1943,7 @@ static ssize_t http2_send(struct connectdata *conn, int sockindex, for(i = 0; i < nheader; ++i) { acc += nva[i].namelen + nva[i].valuelen; - DEBUGF(infof(conn->data, "h2 header: %.*s:%.*s\n", + H2BUGF(infof(conn->data, "h2 header: %.*s:%.*s\n", nva[i].namelen, nva[i].name, nva[i].valuelen, nva[i].value)); } @@ -1975,7 +1981,7 @@ static ssize_t http2_send(struct connectdata *conn, int sockindex, Curl_safefree(nva); if(stream_id < 0) { - DEBUGF(infof(conn->data, "http2_send() send error\n")); + H2BUGF(infof(conn->data, "http2_send() send error\n")); *err = CURLE_SEND_ERROR; return -1; } @@ -1994,7 +2000,7 @@ static ssize_t http2_send(struct connectdata *conn, int sockindex, } if(should_close_session(httpc)) { - DEBUGF(infof(conn->data, "http2_send: nothing to do in this session\n")); + H2BUGF(infof(conn->data, "http2_send: nothing to do in this session\n")); *err = CURLE_HTTP2; return -1; } @@ -2152,7 +2158,7 @@ CURLcode Curl_http2_switched(struct connectdata *conn, return CURLE_HTTP2; } - DEBUGF(infof(data, "nghttp2_session_mem_recv() returns %zd\n", nproc)); + H2BUGF(infof(data, "nghttp2_session_mem_recv() returns %zd\n", nproc)); if((ssize_t)nread == nproc) { httpc->inbuflen = 0; @@ -2172,7 +2178,7 @@ CURLcode Curl_http2_switched(struct connectdata *conn, } if(should_close_session(httpc)) { - DEBUGF(infof(data, + H2BUGF(infof(data, "nghttp2_session_send(): nothing to do in this session\n")); return CURLE_HTTP2; }