debug info

Signed-off-by: zhuangbowei.zbw <zhuangbowei.zbw@alibaba-inc.com>

Author: WaberZhuang

net/http/client.cpp

@@ -131,44 +131,41 @@ class PooledDialer {
     // Factory: full CONNECT tunnel handshake sequence.
     // DNS resolve proxy -> TCP -> [TLS to proxy] -> CONNECT handshake -> TLS to target.
     ISocketStream* make_tunnel_stream(const StoredURL& proxy_url, std::string_view target_host,
-                                      uint16_t target_port, const Headers* headers, uint64_t timeout) {
+                                      uint16_t target_port, const Headers* headers) {
+        LOG_DEBUG("CONNECT tunnel: begin, proxy=`:` target=`:`",
+                  proxy_url.host_no_port(), proxy_url.port(), target_host, target_port);
         auto proxy_ip = resolver->resolve(proxy_url.host_no_port());
         if (proxy_ip.undefined())
             LOG_ERROR_RETURN(ENOENT, nullptr, "CONNECT tunnel: DNS resolve failed for proxy `", proxy_url.host_no_port());
         EndPoint proxy_ep(proxy_ip, proxy_url.port());
-        tcpsock->timeout(timeout);
         auto stream = tcpsock->connect(proxy_ep);
         if (!stream) {
             resolver->discard_cache(proxy_url.host_no_port(), proxy_ip);
             LOG_ERRNO_RETURN(0, nullptr, "CONNECT tunnel: failed to connect to proxy");
         }
-        stream->timeout(timeout);
+        LOG_DEBUG("CONNECT tunnel: connected to proxy `", proxy_ep);
         if (proxy_url.secure()) {
-            auto tls = new_tls_stream(tls_ctx, stream, SecurityRole::Client, true);
-            if (!tls) {
-                delete stream;
+            stream = new_tls_stream(tls_ctx, stream, SecurityRole::Client, true);
+            if (!stream)
                 LOG_ERRNO_RETURN(0, nullptr, "CONNECT tunnel: TLS to proxy failed");
-            }
-            stream = tls;
             tls_stream_set_hostname(stream, std::string(proxy_url.host_no_port()).c_str());
         }
-        if (do_connect_handshake(stream, target_host, target_port, headers, timeout) != 0) {
+        if (do_connect_handshake(stream, target_host, target_port, headers) != 0) {
             delete stream;
             return nullptr;
         }
-        auto tls = new_tls_stream(tls_ctx, stream, SecurityRole::Client, true);
-        if (!tls) {
-            delete stream;
+        LOG_DEBUG("CONNECT tunnel: handshake done, wrapping TLS to target `", target_host);
+        stream = new_tls_stream(tls_ctx, stream, SecurityRole::Client, true);
+        if (!stream)
             LOG_ERRNO_RETURN(0, nullptr, "CONNECT tunnel: TLS to target failed");
-        }
-        stream = tls;
         tls_stream_set_hostname(stream, std::string(target_host).c_str());
+        LOG_DEBUG("CONNECT tunnel: established to target `", target_host);
         return stream;
     }
 
     // Send CONNECT request and verify 2xx response.
     int do_connect_handshake(ISocketStream* stream, std::string_view target_host,
-                             uint16_t target_port, const Headers* headers, uint64_t timeout) {
+                             uint16_t target_port, const Headers* headers) {
         char buf[4096];
         estring authority;
         authority.appends(target_host, ":", target_port);
@@ -179,14 +176,16 @@ class PooledDialer {
         }
         if (req.send_header(stream) < 0)
             LOG_ERRNO_RETURN(0, -1, "CONNECT tunnel: failed to send CONNECT request");
+        LOG_DEBUG("CONNECT tunnel: sent CONNECT `", authority);
 
         // Response needs room for receive_bytes' MAX_TRANSFER_BYTES + RESERVED_INDEX_SIZE.
         char rbuf[8192];
         Response resp(rbuf, (uint16_t)sizeof(rbuf));
         resp.reset(stream, false);
-        if (resp.receive_header(timeout) != 0)
+        if (resp.receive_header() != 0)
             LOG_ERRNO_RETURN(0, -1, "CONNECT tunnel: failed to read proxy response");
         auto sc = resp.status_code();
+        LOG_DEBUG("CONNECT tunnel: proxy response status `", sc);
         if (sc < 200 || sc >= 300)
             LOG_ERROR_RETURN(EINVAL, -1, "CONNECT tunnel: proxy returned status `", sc);
         return 0;
@@ -200,7 +199,7 @@ ISocketStream* PooledDialer::dial(Client::Operation* op, Timeout tmo) {
     if (proxy && op->req.secure()) {
         auto key = make_tunnel_key(*proxy, op->req.host_no_port(), op->req.port(), &op->proxy_header);
         return tcp_pool->connect(key, [&]() -> ISocketStream* {
-            return make_tunnel_stream(*proxy, op->req.host_no_port(), op->req.port(), &op->proxy_header, tmo.timeout());
+            return make_tunnel_stream(*proxy, op->req.host_no_port(), op->req.port(), &op->proxy_header);
         });
     }
 

net/http/server.cpp

@@ -302,25 +302,29 @@ class ForwardProxyHandler: public ProxyHandler {
                      {this, &default_forward_proxy_modifier},
                      client, client_ownership) {}
 
-    int tunnel_copy(ISocketStream *src, ISocketStream *dst) {
+    int tunnel_copy(ISocketStream *src, ISocketStream *dst, const char* tag) {
         const size_t buf_size = 65536;
         char seg_buf[buf_size + 4096];
         char *aligned_buf = (char*) (((uint64_t)(&seg_buf[0]) + 4095) / 4096 * 4096);
 
+        LOG_DEBUG("tunnel_copy ` start", tag);
         while (true) {
+            LOG_DEBUG("tunnel_copy ` waiting recv", tag);
             ssize_t rc = src->recv(aligned_buf, buf_size);
+            LOG_DEBUG("tunnel_copy ` recv=`", tag, rc);
             if (rc == 0) {
-                LOG_DEBUG("end of stream");
+                LOG_DEBUG("tunnel_copy ` end of stream", tag);
                 break;
             }
             if (rc < 0) {
-                LOG_ERRNO_RETURN(0, -1, "read src stream failed");
+                LOG_ERRNO_RETURN(0, -1, "tunnel_copy ` read src stream failed", tag);
             }
             ssize_t wc = dst->write(aligned_buf, rc);
+            LOG_DEBUG("tunnel_copy ` write=` recv=`", tag, wc, rc);
             if (wc != rc)
-                LOG_ERRNO_RETURN(0, -1, "write dst stream failed", VALUE(wc), VALUE(rc));
+                LOG_ERRNO_RETURN(0, -1, "tunnel_copy ` write dst stream failed", tag, VALUE(wc), VALUE(rc));
         }
-
+        LOG_DEBUG("tunnel_copy ` exit", tag);
         return 0;
     }
 
@@ -344,17 +348,19 @@ class ForwardProxyHandler: public ProxyHandler {
             DEFER(delete server_stream);
 
             auto client_stream = req.get_socket_stream();
+            LOG_DEBUG("CONNECT: target ` connected, sending 200", req.target());
             resp.set_result(200, "Connection Established");
             resp.send();
+            LOG_DEBUG("CONNECT: 200 Connection Established sent, starting tunnel");
             bool stopped = false;
 
             auto th = photon::thread_enable_join(photon::thread_create11([&, other=photon::CURRENT]{
-                tunnel_copy(server_stream, client_stream);
+                tunnel_copy(server_stream, client_stream, "downlink(target->client)");
                 if (!stopped)
                     photon::thread_interrupt(other, ECANCELED);
             }));
 
-            tunnel_copy(client_stream, server_stream);
+            tunnel_copy(client_stream, server_stream, "uplink(client->target)");
             stopped = true;
 
             photon::thread_interrupt((thread*)th, ECANCELED);

net/security-context/tls-stream.cpp

@@ -477,14 +477,18 @@ class TLSSocketStream : public ForwardSocketStream {
 #endif
 
     static int ssbio_bwrite(BIO* b, const char* buf, int cnt) {
+        LOG_DEBUG("TLS BIO write enter: req=`", cnt);
         auto ret = get_bio_sockstream(b)->write(buf, cnt);
         PRESERVE_FP_ACROSS_YIELD(ret);
+        LOG_DEBUG("TLS BIO write exit: req=` ret=`", cnt, ret);
         return ret;
     }
 
     static int ssbio_bread(BIO* b, char* buf, int cnt) {
+        LOG_DEBUG("TLS BIO read enter: req=`", cnt);
         auto ret = get_bio_sockstream(b)->recv(buf, cnt);
         PRESERVE_FP_ACROSS_YIELD(ret);
+        LOG_DEBUG("TLS BIO read exit: req=` ret=`", cnt, ret);
         return ret;
     }
 #undef PRESERVE_FP_ACROSS_YIELD