Merge pull request #2194 from toru/resp-probe

A more complete response probing construct

h2o-probes.d

@@ -26,5 +26,7 @@ provider h2o {
     probe receive_request(uint64_t conn_id, uint64_t req_id, int http_version);
     probe receive_request_header(uint64_t conn_id, uint64_t req_id, const char *name, size_t name_len, const char *value,
                                  size_t value_len);
-    probe send_response_status(uint64_t conn_id, uint64_t req_id, int status);
+    probe send_response(uint64_t conn_id, uint64_t req_id, int status);
+    probe send_response_header(uint64_t conn_id, uint64_t req_id, const char *name, size_t name_len, const char *value,
+                               size_t value_len);
 };

lib/http1.c

@@ -947,7 +947,7 @@ void finalostream_send(h2o_ostream_t *_self, h2o_req_t *_req, h2o_sendvec_t *inb
         } else {
             bufs[bufcnt].base = h2o_mem_alloc_pool(&conn->req.pool, char, headers_est_size);
         }
-        h2o_probe_log_response_status(&conn->req, conn->_req_index);
+        h2o_probe_log_response(&conn->req, conn->_req_index);
         bufs[bufcnt].len = flatten_headers(bufs[bufcnt].base, &conn->req, connection);
         if (pull_mode == IS_PULL) {
             pull_mode = LASTBUF_IS_PULL;

lib/http2/stream.c

@@ -331,7 +331,7 @@ void finalostream_send(h2o_ostream_t *self, h2o_req_t *req, h2o_sendvec_t *bufs,
             send_refused_stream(conn, stream);
             return;
         }
-        h2o_probe_log_response_status(&stream->req, stream->stream_id);
+        h2o_probe_log_response(&stream->req, stream->stream_id);
         if (send_headers(conn, stream) != 0)
             return;
     /* fallthru */

lib/probes_.h

@@ -82,6 +82,12 @@ __attribute__((noinline)) static void h2o_probe_request_header(h2o_req_t *req, u
     H2O_PROBE_CONN(RECEIVE_REQUEST_HEADER, req->conn, req_index, name.base, name.len, value.base, value.len);
 }
 
+__attribute__((noinline)) static void h2o_probe_response_header(h2o_req_t *req, uint64_t req_index, h2o_iovec_t name,
+                                                                h2o_iovec_t value)
+{
+    H2O_PROBE_CONN(SEND_RESPONSE_HEADER, req->conn, req_index, name.base, name.len, value.base, value.len);
+}
+
 static inline void h2o_probe_log_request(h2o_req_t *req, uint64_t req_index)
 {
     H2O_PROBE_CONN(RECEIVE_REQUEST, req->conn, req_index, req->version);
@@ -98,9 +104,21 @@ static inline void h2o_probe_log_request(h2o_req_t *req, uint64_t req_index)
     }
 }
 
-static inline void h2o_probe_log_response_status(h2o_req_t *req, uint64_t req_index)
+static inline void h2o_probe_log_response(h2o_req_t *req, uint64_t req_index)
 {
-    H2O_PROBE_CONN(SEND_RESPONSE_STATUS, req->conn, req_index, req->res.status);
+    H2O_PROBE_CONN(SEND_RESPONSE, req->conn, req_index, req->res.status);
+    if (H2O_CONN_IS_PROBED(SEND_RESPONSE_HEADER, req->conn)) {
+        if (req->res.content_length != SIZE_MAX) {
+            char buf[sizeof(H2O_SIZE_T_LONGEST_STR)];
+            size_t len = (size_t)sprintf(buf, "%zu", req->res.content_length);
+            h2o_probe_response_header(req, req_index, H2O_TOKEN_CONTENT_LENGTH->buf, h2o_iovec_init(buf, len));
+        }
+        size_t i;
+        for (i = 0; i != req->res.headers.size; ++i) {
+            h2o_header_t *h = req->res.headers.entries + i;
+            h2o_probe_response_header(req, req_index, *h->name, h->value);
+        }
+    }
 }
 
 #endif

t/90dtrace.t

@@ -53,7 +53,8 @@ if ($tracer_pid == 0) {
         exec qw(bpftrace -v -B none -p), $server->{pid}, "-e", <<'EOT';
 usdt::h2o:receive_request {printf("*** %llu:%llu version %d.%d ***\n", arg0, arg1, arg2 / 256, arg2 % 256)}
 usdt::h2o:receive_request_header {printf("%s: %s\n", str(arg2, arg3), str(arg4, arg5))}
-usdt::h2o:send_response_status {printf("%llu:%llu status:%u\n", arg0, arg1, arg2)}
+usdt::h2o:send_response {printf("%llu:%llu status:%u\n", arg0, arg1, arg2)}
+usdt::h2o:send_response_header {printf("%s: %s\n", str(arg2, arg3), str(arg4, arg5))}
 EOT
         die "failed to spawn bpftrace:$!";
     } else {
@@ -73,7 +74,7 @@ EOT
 }
 EOT
             "-n", <<'EOT',
-:h2o::send_response_status {
+:h2o::send_response {
     printf("\nXXXX%u:%u status:%u\n", arg0, arg1, arg2);
 }
 EOT
@@ -91,7 +92,7 @@ while (1) {
         $read_trace = sub {
             seek $fh, $off, 0
                 or die "seek failed:$!";
-            read $fh, my $bytes, 10000;
+            read $fh, my $bytes, 13000;
             $bytes = ''
                 unless defined $bytes;
             $off += length $bytes;
@@ -138,6 +139,9 @@ run_with_curl($server, sub {
     like $trace, qr{^:authority: 127\.0\.0\.1:$port$}m;
     like $trace, qr{^:path: /$}m;
     like $trace, qr{^\d+:1 status:200}m;
+    like $trace, qr{content-length: 6}m;
+    like $trace, qr{content-type: text/plain}m;
+    like $trace, qr{accept-ranges: bytes}m;
 });
 
 # wait until the server and the tracer exits