Fix %<chi> with PROXY Protocol

doc/admin-guide/logging/formatting.en.rst

@@ -487,7 +487,8 @@ incoming/outgoing ports, and network interfaces used during transactions.
 ===== ============== ==========================================================
 Field Source         Description
 ===== ============== ==========================================================
-chi   Client         IP address of the client's host.
+chi   Client         IP address of the client's host. If :ref:`Proxy Protocol <proxy-protocol>`
+                     is used, this represents the IP address of the previous hop.
 chih  Client         IP address of the client's host, in hexadecimal.
 hii   Proxy          IP address for the proxy's incoming interface (to which
                      the client connected).

iocore/net/P_NetVConnection.h

@@ -28,11 +28,7 @@ inline sockaddr const *
 NetVConnection::get_remote_addr()
 {
   if (!got_remote_addr) {
-    if (pp_info.version != ProxyProtocolVersion::UNDEFINED) {
-      set_remote_addr(get_proxy_protocol_src_addr());
-    } else {
-      set_remote_addr();
-    }
+    set_remote_addr();
     got_remote_addr = true;
   }
   return &remote_addr.sa;

iocore/net/SSLNetVConnection.cc

@@ -439,8 +439,7 @@ SSLNetVConnection::read_raw_data()
       // what we want now.
       void *payload = nullptr;
       if (!pp_ipmap->contains(get_remote_addr(), &payload)) {
-        Debug("proxyprotocol", "proxy protocol src IP is NOT in the configured allowlist of trusted IPs - "
-                               "closing connection");
+        Debug("proxyprotocol", "Source IP is NOT in the configured allowlist of trusted IPs - closing connection");
         r = -ENOTCONN; // Need a quick close/exit here to refuse the connection!!!!!!!!!
         goto proxy_protocol_bypass;
       } else {
@@ -455,7 +454,6 @@ SSLNetVConnection::read_raw_data()
 
     if (this->has_proxy_protocol(buffer, &r)) {
       Debug("proxyprotocol", "ssl has proxy protocol header");
-      set_remote_addr(get_proxy_protocol_src_addr());
       if (is_debug_tag_set("proxyprotocol")) {
         IpEndpoint dst;
         dst.sa = *(this->get_proxy_protocol_dst_addr());

proxy/ProtocolProbeSessionAccept.cc

@@ -108,7 +108,7 @@ struct ProtocolProbeTrampoline : public Continuation, public ProtocolProbeSessio
         void *payload = nullptr;
         if (!pp_ipmap->contains(netvc->get_remote_addr(), &payload)) {
           Debug("proxyprotocol",
-                "ioCompletionEvent: proxy protocol src IP is NOT in the configured allowlist of trusted IPs - closing connection");
+                "ioCompletionEvent: Source IP is NOT in the configured allowlist of trusted IPs - closing connection");
           goto done;
         } else {
           char new_host[INET6_ADDRSTRLEN];
@@ -123,7 +123,6 @@ struct ProtocolProbeTrampoline : public Continuation, public ProtocolProbeSessio
 
       if (netvc->has_proxy_protocol(reader)) {
         Debug("proxyprotocol", "ioCompletionEvent: http has proxy protocol header");
-        netvc->set_remote_addr(netvc->get_proxy_protocol_src_addr());
       } else {
         Debug("proxyprotocol",
               "ioCompletionEvent: proxy protocol was enabled, but required header was not present in the transaction - "

proxy/http/HttpTransactHeaders.cc

@@ -960,18 +960,27 @@ HttpTransactHeaders::add_forwarded_field_to_request(HttpTransact::State *s, HTTP
 
     ts::LocalBufferWriter<1024> hdr;
 
-    if (optSet[HttpForwarded::FOR] and ats_is_ip(&s->client_info.src_addr.sa)) {
+    IpEndpoint src_addr = s->client_info.src_addr;
+    if (s->state_machine->ua_txn && s->state_machine->ua_txn->get_netvc()) {
+      const ProxyProtocol &pp = s->state_machine->ua_txn->get_netvc()->get_proxy_protocol_info();
+
+      if (pp.version != ProxyProtocolVersion::UNDEFINED) {
+        src_addr = pp.src_addr;
+      }
+    }
+
+    if (optSet[HttpForwarded::FOR] and ats_is_ip(&src_addr.sa)) {
       // NOTE:  The logic within this if statement assumes that hdr is empty at this point.
 
       hdr << "for=";
 
-      bool is_ipv6 = ats_is_ip6(&s->client_info.src_addr.sa);
+      bool is_ipv6 = ats_is_ip6(&src_addr.sa);
 
       if (is_ipv6) {
         hdr << "\"[";
       }
 
-      if (ats_ip_ntop(&s->client_info.src_addr.sa, hdr.auxBuffer(), hdr.remaining()) == nullptr) {
+      if (ats_ip_ntop(&src_addr.sa, hdr.auxBuffer(), hdr.remaining()) == nullptr) {
         Debug("http_trans", "[add_forwarded_field_to_outgoing_request] ats_ip_ntop() call failed");
         return;
       }

tests/gold_tests/proxy_protocol/gold/access.gold

@@ -0,0 +1,3 @@
+127.0.0.1 127.0.0.1
+127.0.0.1 127.0.0.1
+127.0.0.1 198.51.100.1

tests/gold_tests/proxy_protocol/gold/test_case_0_stdout.gold

@@ -2,7 +2,7 @@
 ``
   "headers": {
 ``
-    "Forwarded": "for=127.0.0.1;proto=http",
+    "Forwarded": "for=127.0.0.1;by=127.0.0.1;proto=http",
 ``
   },
 ``

tests/gold_tests/proxy_protocol/gold/test_case_1_stdout.gold

@@ -2,7 +2,7 @@
 ``
   "headers": {
 ``
-    "Forwarded": "for=127.0.0.1;proto=https",
+    "Forwarded": "for=127.0.0.1;by=127.0.0.1;proto=https",
 ``
   },
 ``

tests/gold_tests/proxy_protocol/gold/test_case_2_stdout.gold

@@ -0,0 +1,14 @@
+HTTP/1.1 200 OK
+Server: ATS/``
+Date: ``
+Age: ``
+
+{
+``
+  "headers":``{
+``
+    "Forwarded":``"for=198.51.100.1;by=127.0.0.1;proto=http",
+``
+  },
+``
+}

tests/gold_tests/proxy_protocol/proxy_protocol.test.py

@@ -16,6 +16,7 @@
 #  See the License for the specific language governing permissions and
 #  limitations under the License.
 
+import os
 import sys
 
 Test.Summary = 'Test PROXY Protocol'
@@ -49,13 +50,25 @@ def setupTS(self):
         self.ts.Disk.records_config.update({
             "proxy.config.http.server_ports": f"{self.ts.Variables.port}:pp {self.ts.Variables.ssl_port}:ssl:pp",
             "proxy.config.http.proxy_protocol_allowlist": "127.0.0.1",
-            "proxy.config.http.insert_forwarded": "for|proto",
+            "proxy.config.http.insert_forwarded": "for|by=ip|proto",
             "proxy.config.ssl.server.cert.path": f"{self.ts.Variables.SSLDir}",
             "proxy.config.ssl.server.private_key.path": f"{self.ts.Variables.SSLDir}",
             "proxy.config.diags.debug.enabled": 1,
             "proxy.config.diags.debug.tags": "proxyprotocol",
         })
 
+        self.ts.Disk.logging_yaml.AddLines(
+            '''
+logging:
+  formats:
+    - name: access
+      format: '%<chi> %<pps>'
+
+  logs:
+    - filename: access
+      format: access
+'''.split("\n"))
+
     def addTestCase0(self):
         """
         Incoming PROXY Protocol v1 on TCP port
@@ -82,9 +95,36 @@ def addTestCase1(self):
         tr.StillRunningAfter = self.httpbin
         tr.StillRunningAfter = self.ts
 
+    def addTestCase2(self):
+        """
+        Test with netcat
+        """
+        tr = Test.AddTestRun()
+        tr.Processes.Default.Command = f"echo 'PROXY TCP4 198.51.100.1 198.51.100.2 51137 80\r\nGET /get HTTP/1.1\r\nHost: 127.0.0.1:80\r\n' | nc localhost {self.ts.Variables.port}"
+        tr.Processes.Default.ReturnCode = 0
+        tr.Processes.Default.Streams.stdout = "gold/test_case_2_stdout.gold"
+        tr.StillRunningAfter = self.httpbin
+        tr.StillRunningAfter = self.ts
+
+    def addTestCase99(self):
+        """
+        check access log
+        """
+        Test.Disk.File(os.path.join(self.ts.Variables.LOGDIR, 'access.log'), exists=True, content='gold/access.gold')
+
+        # Wait for log file to appear, then wait one extra second to make sure TS is done writing it.
+        tr = Test.AddTestRun()
+        tr.Processes.Default.Command = (
+            os.path.join(Test.Variables.AtsTestToolsDir, 'condwait') + ' 60 1 -f ' +
+            os.path.join(self.ts.Variables.LOGDIR, 'access.log')
+        )
+        tr.Processes.Default.ReturnCode = 0
+
     def run(self):
         self.addTestCase0()
         self.addTestCase1()
+        self.addTestCase2()
+        self.addTestCase99()
 
 
 ProxyProtocolTest().run()