search

apache / trafficserver

Apache Traffic Server™ is a fast, scalable and extensible HTTP/1.1 and HTTP/2 compliant caching proxy server.
https://trafficserver.apache.org/
Apache License 2.0
1.8k stars 793 forks source link

Mapping HTTP to HTTPS does not work with parent proxy #11543

Open cfiehe opened 1 month ago

cfiehe commented 1 month ago

I try to map a plain HTTP request from a client to a HTTPS destination using:

map http://127.0.0.1:8080/docker/ https://download.docker.com/linux/ubuntu/

The mapping itself is working and the URL is rewritten, but the request fails with:

# curl -v -I http://127.0.0.1:8080/docker/
*   Trying 127.0.0.1:8080...
* Connected to 127.0.0.1 (127.0.0.1) port 8080
> HEAD /docker/ HTTP/1.1
> Host: 127.0.0.1:8080
> User-Agent: curl/8.5.0
> Accept: */*
>
< HTTP/1.1 502 Next Hop Connection Failed
HTTP/1.1 502 Next Hop Connection Failed
< Date: Fri, 12 Jul 2024 20:03:42 GMT
Date: Fri, 12 Jul 2024 20:03:42 GMT
< Connection: keep-alive
Connection: keep-alive
< Server: ATS/9.2.3
Server: ATS/9.2.3
< Cache-Control: no-store
Cache-Control: no-store
< Content-Type: text/html
Content-Type: text/html
< Content-Language: en
Content-Language: en
< Content-Length: 207
Content-Length: 207

ATS cannot access the resource directly, the request must pass our corporate proxy. I have defined a corresponding parent proxy definition:

dest_host=download.docker.com parent="<CORPORATE-PROXY-IP>:<CORPORATE-PROXY-PORT>" parent_is_proxy=true

When I use HTTP instead of HTTPS in the destination URL of the mapping rule, it is working. It seems to me, that ATS does not use the CONNECT method in order to establish a connection to the destination via the corporate proxy.

I have turned on debug logging, but I am not sure, if it helps to narrow down the issue:

[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <ProtocolProbeSessionAccept.cc:187 (mainEvent)> (http) probe needs data, read..
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpSessionAccept.cc:48 (accept)> (http_seq) [HttpSessionAccept:mainEvent 0x78a1c001ec40] accepted connection from 127.0.0.1:36954 transport type = 1
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <Http1ClientSession.cc:191 (new_connection)> (http_cs) [2] session born, netvc 0x78a1c001ec40
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <Http1ClientSession.cc:430 (release)> (http_cs) [2] data already in buffer, starting new transaction
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpSM.h:174 (PostDataBuffers)> (http_redirect) [PostDataBuffers::PostDataBuffers]
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <ProxyTransaction.cc:50 (new_transaction)> (http_txn) [2] Starting transaction 1 using sm [1]
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpSM.cc:2740 (main_handler)> (http) [1] VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY, 100
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpSM.cc:686 (state_read_client_request_header)> (http) [1] [&HttpSM::state_read_client_request_header, VC_EVENT_READ_READY/TS_EVENT_VCONN_READ_READY]
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpSM.cc:842 (state_read_client_request_header)> (http) [1] done parsing client request header
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpTransact.cc:5553 (set_client_request_state)> (http_trans) [1] set req cont length to -1
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpTransact.cc:1364 (ModifyRequest)> (http_trans) [1] START HttpTransact::ModifyRequest
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpTransact.cc:1438 (ModifyRequest)> (http_trans) [1] END HttpTransact::ModifyRequest
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpTransact.cc:1440 (ModifyRequest)> (http_trans) Next action SM_ACTION_API_READ_REQUEST_HDR; HttpTransact::StartRemapRequest
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpSM.cc:7635 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_UNDEFINED -> SM_ACTION_API_READ_REQUEST_HDR
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpTransact.cc:975 (StartRemapRequest)> (http_trans) [1] START HttpTransact::StartRemapRequest
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpTransact.cc:995 (StartRemapRequest)> (http_trans) [1] Before Remapping:
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HdrHeap.cc:54 (obj_describe)> (http) HTTP_HEADER 0x78a21635b088: [T: 3, L:   48, OBJFLAGS: 0]  
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HTTP.cc:549 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x78a21635b308, METHOD: "HEAD", METHOD_LEN: 4, FIELDS: 0x78a21635b0b8]
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HdrHeap.cc:54 (obj_describe)> (http) URL 0x78a21635b308: [T: 2, L:  112, OBJFLAGS: 0]  
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <URL.cc:1731 (url_describe)> (http) [URLTYPE: 1, SWKSIDX: 99,
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <URL.cc:1732 (url_describe)> (http)     SCHEME: "http", SCHEME_LEN: 4,
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <URL.cc:1734 (url_describe)> (http)     USER: "", USER_LEN: 0,
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <URL.cc:1735 (url_describe)> (http)     PASSWORD: "", PASSWORD_LEN: 0,
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <URL.cc:1737 (url_describe)> (http)     HOST: "", HOST_LEN: 0,
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <URL.cc:1738 (url_describe)> (http)     PORT: "", PORT_LEN: 0, PORT_NUM: 0
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <URL.cc:1740 (url_describe)> (http)     PATH: "docker/", PATH_LEN: 7,
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <URL.cc:1741 (url_describe)> (http)     PARAMS: "", PARAMS_LEN: 0,
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <URL.cc:1743 (url_describe)> (http)     QUERY: "", QUERY_LEN: 0,
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <URL.cc:1745 (url_describe)> (http)     FRAGMENT: "", FRAGMENT_LEN: 0]
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HdrHeap.cc:54 (obj_describe)> (http) MIME_HEADER 0x78a21635b0b8: [T: 4, L:  592, OBJFLAGS: 0]  
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2633 (mime_hdr_describe)> (http)   [PBITS: 0x0008000001000001, SLACC: 0xFFFFFFF2FFFFFFFFFFFFFFFFFFF1FFFF, HEADBLK: 0x78a21635b0f8, TAILBLK: 0x78a21635b0f8]
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2639 (mime_hdr_describe)> (http)   [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HdrHeap.cc:54 (obj_describe)> (http) FIELD_BLOCK 0x78a21635b0f8: [T: 5, L:  528, OBJFLAGS: 0]  
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2658 (mime_field_block_describe)> (http) [FREETOP: 3, NEXTBLK: (nil)]
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2662 (mime_field_block_describe)> (http)   SLOT # 0 (0x78a21635b108), LIVE    
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2670 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30, 
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2672 (mime_field_block_describe)> (http) V: "127.0.0.1:8080", V_LEN: 14, 
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2673 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 22, F: 1]
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2677 (mime_field_block_describe)> (http) 
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2662 (mime_field_block_describe)> (http)   SLOT # 1 (0x78a21635b128), LIVE    
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2670 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64, 
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2672 (mime_field_block_describe)> (http) V: "curl/8.5.0", V_LEN: 10, 
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2673 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1]
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2677 (mime_field_block_describe)> (http) 
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2662 (mime_field_block_describe)> (http)   SLOT # 2 (0x78a21635b148), LIVE    
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2670 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4, 
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2672 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3, 
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2673 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <MIME.cc:2677 (mime_field_block_describe)> (http) 
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpTransact.cc:1007 (StartRemapRequest)> (http_trans) [1] END HttpTransact::StartRemapRequest
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpTransact.cc:1009 (StartRemapRequest)> (http_trans) [1] Checking if transaction wants to upgrade
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpTransact.cc:1016 (StartRemapRequest)> (http_trans) Next action SM_ACTION_API_PRE_REMAP; HttpTransact::PerformRemap
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpSM.cc:7635 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_API_READ_REQUEST_HDR -> SM_ACTION_API_PRE_REMAP
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpTransact.cc:1022 (PerformRemap)> (http_trans) [1] Inside PerformRemap
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpTransact.cc:1023 (PerformRemap)> (http_trans) Next action SM_ACTION_REMAP_REQUEST; HttpTransact::EndRemapRequest
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpSM.cc:7635 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_API_PRE_REMAP -> SM_ACTION_REMAP_REQUEST
[Jul 12 22:08:09.395] [ET_NET 1] DEBUG: <HttpSM.cc:4221 (do_remap_request)> (http_seq) [1] Remapping request
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:1029 (EndRemapRequest)> (http_trans) [1] START HttpTransact::EndRemapRequest
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:1035 (EndRemapRequest)> (http_trans) [1] EndRemapRequest host is download.docker.com
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:1173 (EndRemapRequest)> (http_trans) [1] After Remapping:
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HdrHeap.cc:54 (obj_describe)> (http) HTTP_HEADER 0x78a21635b088: [T: 3, L:   48, OBJFLAGS: 0]  
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HTTP.cc:549 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x78a21635b308, METHOD: "HEAD", METHOD_LEN: 4, FIELDS: 0x78a21635b0b8]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HdrHeap.cc:54 (obj_describe)> (http) URL 0x78a21635b308: [T: 2, L:  112, OBJFLAGS: 0]  
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1731 (url_describe)> (http) [URLTYPE: 2, SWKSIDX: 98,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1732 (url_describe)> (http)     SCHEME: "https", SCHEME_LEN: 5,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1734 (url_describe)> (http)     USER: "", USER_LEN: 0,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1735 (url_describe)> (http)     PASSWORD: "", PASSWORD_LEN: 0,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1737 (url_describe)> (http)     HOST: "download.docker.com", HOST_LEN: 19,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1738 (url_describe)> (http)     PORT: "", PORT_LEN: 0, PORT_NUM: 0
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1740 (url_describe)> (http)     PATH: "linux/ubuntu/", PATH_LEN: 13,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1741 (url_describe)> (http)     PARAMS: "", PARAMS_LEN: 0,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1743 (url_describe)> (http)     QUERY: "", QUERY_LEN: 0,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1745 (url_describe)> (http)     FRAGMENT: "", FRAGMENT_LEN: 0]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HdrHeap.cc:54 (obj_describe)> (http) MIME_HEADER 0x78a21635b0b8: [T: 4, L:  592, OBJFLAGS: 0]  
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2633 (mime_hdr_describe)> (http)   [PBITS: 0x0008000001000001, SLACC: 0xFFFFFFF2FFFFFFFFFFFFFFFFFFF1FFFF, HEADBLK: 0x78a21635b0f8, TAILBLK: 0x78a21635b0f8]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2639 (mime_hdr_describe)> (http)   [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HdrHeap.cc:54 (obj_describe)> (http) FIELD_BLOCK 0x78a21635b0f8: [T: 5, L:  528, OBJFLAGS: 0]  
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2658 (mime_field_block_describe)> (http) [FREETOP: 3, NEXTBLK: (nil)]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2662 (mime_field_block_describe)> (http)   SLOT # 0 (0x78a21635b108), LIVE    
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2670 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30, 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2672 (mime_field_block_describe)> (http) V: "download.docker.com", V_LEN: 19, 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2673 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 27, F: 1]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2677 (mime_field_block_describe)> (http) 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2662 (mime_field_block_describe)> (http)   SLOT # 1 (0x78a21635b128), LIVE    
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2670 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64, 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2672 (mime_field_block_describe)> (http) V: "curl/8.5.0", V_LEN: 10, 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2673 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2677 (mime_field_block_describe)> (http) 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2662 (mime_field_block_describe)> (http)   SLOT # 2 (0x78a21635b148), LIVE    
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2670 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4, 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2672 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3, 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2673 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2677 (mime_field_block_describe)> (http) 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:1192 (EndRemapRequest)> (http_trans) [1] END HttpTransact::EndRemapRequest
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:1198 (EndRemapRequest)> (http_trans) Next action SM_ACTION_API_POST_REMAP; HttpTransact::HandleRequest
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:7635 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_REMAP_REQUEST -> SM_ACTION_API_POST_REMAP
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:1477 (HandleRequest)> (http_trans) [1] START HttpTransact::HandleRequest
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:5553 (set_client_request_state)> (http_trans) [1] set req cont length to -1
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:6460 (is_request_valid)> (http_trans) [1] no request header errors
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:1499 (HandleRequest)> (http_seq) [1] request valid.
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HdrHeap.cc:54 (obj_describe)> (http) HTTP_HEADER 0x78a21635b088: [T: 3, L:   48, OBJFLAGS: 0]  
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HTTP.cc:549 (http_hdr_describe)> (http) [TYPE: REQ, V: 10001, URL: 0x78a21635b308, METHOD: "HEAD", METHOD_LEN: 4, FIELDS: 0x78a21635b0b8]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HdrHeap.cc:54 (obj_describe)> (http) URL 0x78a21635b308: [T: 2, L:  112, OBJFLAGS: 0]  
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1731 (url_describe)> (http) [URLTYPE: 2, SWKSIDX: 98,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1732 (url_describe)> (http)     SCHEME: "https", SCHEME_LEN: 5,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1734 (url_describe)> (http)     USER: "", USER_LEN: 0,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1735 (url_describe)> (http)     PASSWORD: "", PASSWORD_LEN: 0,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1737 (url_describe)> (http)     HOST: "download.docker.com", HOST_LEN: 19,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1738 (url_describe)> (http)     PORT: "", PORT_LEN: 0, PORT_NUM: 0
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1740 (url_describe)> (http)     PATH: "linux/ubuntu/", PATH_LEN: 13,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1741 (url_describe)> (http)     PARAMS: "", PARAMS_LEN: 0,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1743 (url_describe)> (http)     QUERY: "", QUERY_LEN: 0,
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <URL.cc:1745 (url_describe)> (http)     FRAGMENT: "", FRAGMENT_LEN: 0]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HdrHeap.cc:54 (obj_describe)> (http) MIME_HEADER 0x78a21635b0b8: [T: 4, L:  592, OBJFLAGS: 0]  
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2633 (mime_hdr_describe)> (http)   [PBITS: 0x0008000001000001, SLACC: 0xFFFFFFF2FFFFFFFFFFFFFFFFFFF1FFFF, HEADBLK: 0x78a21635b0f8, TAILBLK: 0x78a21635b0f8]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2639 (mime_hdr_describe)> (http)   [CBITS: 0x00000000, T_MAXAGE: 0, T_SMAXAGE: 0, T_MAXSTALE: 0, T_MINFRESH: 0, PNO$: 0]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HdrHeap.cc:54 (obj_describe)> (http) FIELD_BLOCK 0x78a21635b0f8: [T: 5, L:  528, OBJFLAGS: 0]  
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2658 (mime_field_block_describe)> (http) [FREETOP: 3, NEXTBLK: (nil)]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2662 (mime_field_block_describe)> (http)   SLOT # 0 (0x78a21635b108), LIVE    
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2670 (mime_field_block_describe)> (http) [N: "Host", N_LEN: 4, N_IDX: 30, 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2672 (mime_field_block_describe)> (http) V: "download.docker.com", V_LEN: 19, 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2673 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 0, RAWLEN: 27, F: 1]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2677 (mime_field_block_describe)> (http) 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2662 (mime_field_block_describe)> (http)   SLOT # 1 (0x78a21635b128), LIVE    
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2670 (mime_field_block_describe)> (http) [N: "User-Agent", N_LEN: 10, N_IDX: 64, 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2672 (mime_field_block_describe)> (http) V: "curl/8.5.0", V_LEN: 10, 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2673 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 24, F: 1]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2677 (mime_field_block_describe)> (http) 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2662 (mime_field_block_describe)> (http)   SLOT # 2 (0x78a21635b148), LIVE    
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2670 (mime_field_block_describe)> (http) [N: "Accept", N_LEN: 6, N_IDX: 4, 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2672 (mime_field_block_describe)> (http) V: "*/*", V_LEN: 3, 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2673 (mime_field_block_describe)> (http) NEXTDUP: (nil), RAW: 1, RAWLEN: 13, F: 1]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <MIME.cc:2677 (mime_field_block_describe)> (http) 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:2666 (CallOSDNSLookup)> (http) [1] download.docker.com 
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:2680 (CallOSDNSLookup)> (http_trans) Next action SM_ACTION_DNS_LOOKUP; OSDNSLookup
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:7635 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_API_POST_REMAP -> SM_ACTION_DNS_LOOKUP
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:1932 (OSDNSLookup)> (http_trans) [1] Entering HttpTransact::OSDNSLookup
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:1976 (OSDNSLookup)> (http_seq) [1] DNS Lookup successful
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:2014 (OSDNSLookup)> (http_trans) [1] DNS lookup for O.S. successful IP: *Not IP address [0]*
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:2118 (HandleRequestAuthorized)> (http_trans) Next action SM_ACTION_API_OS_DNS; HttpTransact::DecideCacheLookup
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:7635 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_DNS_LOOKUP -> SM_ACTION_API_OS_DNS
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:2197 (DecideCacheLookup)> (http_trans) [1] Will NOT do cache lookup.
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:2198 (DecideCacheLookup)> (http_seq) [1] Will NOT do cache lookup
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:2222 (DecideCacheLookup)> (http_trans) Next action SM_ACTION_API_CACHE_LOOKUP_COMPLETE; LookupSkipOpenServer
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:7635 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_API_OS_DNS -> SM_ACTION_API_CACHE_LOOKUP_COMPLETE
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:2241 (LookupSkipOpenServer)> (http_trans) Next action SM_ACTION_DNS_LOOKUP; PPDNSLookupAPICall
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:7635 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_API_CACHE_LOOKUP_COMPLETE -> SM_ACTION_DNS_LOOKUP
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:4350 (do_hostdb_lookup)> (http_seq) [1] Doing DNS Lookup
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:1757 (PPDNSLookupAPICall)> (http_trans) [1] response_action.handled 0
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:1759 (PPDNSLookupAPICall)> (http_trans) Next action SM_ACTION_DNS_LOOKUP; PPDNSLookup
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:7635 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_DNS_LOOKUP -> SM_ACTION_DNS_LOOKUP
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:4350 (do_hostdb_lookup)> (http_seq) [1] Doing DNS Lookup
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:1788 (PPDNSLookup)> (http_trans) [1] Entering HttpTransact::PPDNSLookup
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:1822 (PPDNSLookup)> (http_trans) [1] DNS lookup for successful IP: <CORPORATE-PROXY-IP>
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:7875 (build_request)> (http_trans) [1] request_sent_time: 1720814889
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:7635 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_DNS_LOOKUP -> SM_ACTION_ORIGIN_SERVER_OPEN
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:5090 (do_http_server_open)> (http_track) [1] entered inside do_http_server_open ][ipv4]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:5123 (do_http_server_open)> (http) [1] open connection to <CORPORATE-PROXY-IP>: <CORPORATE-PROXY-IP><CORPORATE-PROXY-PORT>
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:5126 (do_http_server_open)> (http_seq) [1] Sending request to server
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:6654 (will_this_request_self_loop)> (http_transact) [1] max_proxy_cycles = 0
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:6660 (will_this_request_self_loop)> (http_transact) [1] dst_port = 443 local_port = 8080
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpTransact.cc:6713 (will_this_request_self_loop)> (http_transact) [1] count = 0 <= max_proxy_cycles = 0 : allowing loop
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSessionManager.cc:403 (_acquire_session)> (http_ss) [acquire session] thread pool search failed
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:5501 (do_http_server_open)> (http) [1] calling sslNetProcessor.connect_re
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:2740 (main_handler)> (http) [1] NET_EVENT_OPEN/TS_EVENT_NET_CONNECT, 200
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:1878 (state_http_server_open)> (http_track) [1] entered inside state_http_server_open: NET_EVENT_OPEN/TS_EVENT_NET_CONNECT
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:1879 (state_http_server_open)> (http) [1] [&HttpSM::state_http_server_open, NET_EVENT_OPEN/TS_EVENT_NET_CONNECT]
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <Http1ServerSession.cc:94 (new_connection)> (http_ss) [3] session born, netvc 0x78a208266580
[Jul 12 22:08:09.396] [ET_NET 1] DEBUG: <HttpSM.cc:1908 (state_http_server_open)> (http) [1] setting handler for TCP handshake
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpSM.cc:2740 (main_handler)> (http) [1] EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR, 3
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpSM.cc:1878 (state_http_server_open)> (http_track) [1] entered inside state_http_server_open: EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpSM.cc:1879 (state_http_server_open)> (http) [1] [&HttpSM::state_http_server_open, EVENT_ERROR/TS_EVENT_ERROR/VC_EVENT_ERROR]
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <Http1ServerSession.cc:121 (do_io_close)> (http_ss) [3] session close: nevtc 0x78a208266580
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTransact.cc:3460 (HandleResponse)> (http_trans) [1] Entering HttpTransact::HandleResponse
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTransact.cc:3461 (HandleResponse)> (http_seq) [1] Response received
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTransact.cc:3468 (HandleResponse)> (http_trans) [1] response_received_time: 1720814889
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTransact.cc:3483 (HandleResponse)> (http_seq) [1] Response not valid
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTransact.cc:3618 (handle_response_from_parent)> (http_trans) [1] (hrfp)
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTransact.cc:3664 (handle_response_from_parent)> (http_trans) [1] [hrfp] connection not alive
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTransact.cc:3677 (handle_response_from_parent)> (http_trans) [1] [0] failed to connect to parent <CORPORATE-PROXY-IP>
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTransact.cc:3703 (handle_response_from_parent)> (http_trans) [1] [handle_response_from_parent] 1 per parent attempts exhausted
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTransact.cc:217 (markParentDown)> (http_trans) [1] enable_parent_timeout_markdowns: 0, disable_parent_markdowns: 0
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTransact.cc:3974 (handle_server_connection_not_open)> (http_trans) [1] (hscno)
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTransact.cc:3975 (handle_server_connection_not_open)> (http_seq) [1] Entering HttpTransact::handle_server_connection_not_open
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpSM.cc:5667 (mark_host_failure)> (http) [1] hostdb increment IP failcount <CORPORATE-PROXY-IP><CORPORATE-PROXY-PORT> to 1
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpSM.cc:4483 (do_hostdb_update_if_necessary)> (http) [1] server info = <CORPORATE-PROXY-IP><CORPORATE-PROXY-PORT>
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTransactHeaders.cc:1151 (add_server_header_to_response)> (http_trans) Adding Server: ATS/9.2.3
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTransact.cc:7610 (handle_parent_died)> (http_trans) Next action SM_ACTION_SEND_ERROR_CACHE_NOOP; nullptr
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpSM.cc:7635 (call_transact_and_set_next_state)> (http) [1] State Transition: SM_ACTION_ORIGIN_SERVER_OPEN -> SM_ACTION_SEND_ERROR_CACHE_NOOP
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTunnel.cc:626 (add_producer)> (http_tunnel) [1] adding producer 'internal msg'
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTunnel.cc:681 (add_consumer)> (http_tunnel) [1] adding consumer 'user agent'
[Jul 12 22:08:09.397] [ET_NET 1] DEBUG: <HttpTunnel.cc:728 (tunnel_run)> (http_tunnel) tunnel_run started, p_arg is provided
[Jul 12 22:08:09.398] [ET_NET 1] DEBUG: <HttpTunnel.cc:1344 (consumer_handler)> (http_tunnel) [1] consumer_handler [user agent VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jul 12 22:08:09.398] [ET_NET 1] DEBUG: <HttpSM.cc:3365 (tunnel_handler_ua)> (http) [1] [&HttpSM::tunnel_handler_ua, VC_EVENT_WRITE_COMPLETE/TS_EVENT_VCONN_WRITE_COMPLETE]
[Jul 12 22:08:09.398] [ET_NET 1] DEBUG: <HttpSM.cc:2740 (main_handler)> (http) [1] HTTP_TUNNEL_EVENT_DONE, 2301
[Jul 12 22:08:09.398] [ET_NET 1] DEBUG: <HttpSM.cc:3035 (tunnel_handler)> (http) [1] [&HttpSM::tunnel_handler, HTTP_TUNNEL_EVENT_DONE]
[Jul 12 22:08:09.398] [ET_NET 1] DEBUG: <HttpSM.cc:8594 (clear)> (http_redirect) [PostDataBuffers::clear]
[Jul 12 22:08:09.398] [ET_NET 1] DEBUG: <HttpSM.cc:7331 (kill_this)> (http_seq) [1] Logging transaction
[Jul 12 22:08:09.398] [ET_NET 1] DEBUG: <Http1ClientSession.cc:433 (release)> (http_cs) [2] initiating io for next header
[Jul 12 22:08:09.398] [ET_NET 1] DEBUG: <HttpSM.cc:7381 (kill_this)> (http) [1] deallocating sm
[Jul 12 22:08:09.398] [ET_NET 1] DEBUG: <Http1ClientSession.cc:374 (state_keep_alive)> (http_cs) [2] [&Http1ClientSession::state_keep_alive, VC_EVENT_EOS/TS_EVENT_VCONN_EOS]
[Jul 12 22:08:09.398] [ET_NET 1] DEBUG: <Http1ClientSession.cc:265 (do_io_close)> (http_cs) [2] session closed
[Jul 12 22:08:09.398] [ET_NET 1] DEBUG: <Http1ClientSession.cc:75 (destroy)> (http_cs) [2] session destroy

Has anybody an idea, how to solve the issue?

mlibbey commented 1 month ago

Think you'd need the CONNECT to be initiated by the client like curl -p -v -x 127.0.0.1:8080 https://download.docker.com/linux/ubuntu/

(and I think you'd do the mapping like map https://download.docker.com https://download.docker.com:443 )

cfiehe commented 1 month ago

Yes, when the client addressing scheme could have be modified, it would work, unfortunately, that is not the case. The example above should just reflect the use case. I have to find a solution hat allows to reverse proxy a resource that is only reachable via a forward proxy and requires HTTPS, but the incoming request is plain HTTP. Also sending a redirect to tell the client to use HTTPS is not an option.

mlibbey commented 1 month ago

Think your next debugging step would be to get on the node running ATS, and find a (verbose) curl that works -- that should help in figuring out how to mimic the curl with ATS config.

maskit commented 1 month ago

@cfiehe Do you use OpenSSL 3.2+ by any chance? If you do, the cause can be https://github.com/apache/trafficserver/issues/11465.