Unverified Commit 0630bb21 authored by Daniel Stenberg's avatar Daniel Stenberg
Browse files

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.
parent 811d96e9
Loading
Loading
Loading
Loading
+66 −60
Original line number Diff line number Diff line
@@ -5,7 +5,7 @@
 *                            | (__| |_| |  _ <| |___
 *                             \___|\___/|_| \_\_____|
 *
 * Copyright (C) 1998 - 2017, Daniel Stenberg, <daniel@haxx.se>, et al.
 * Copyright (C) 1998 - 2018, Daniel Stenberg, <daniel@haxx.se>, 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;
  }