Troubleshooting the "EXCEPTION(invalid_request): Request could not be handled
Last Error: URL could not be parsed for matching purposes '' failed because: Scheme was not delimited by '://'"
Troubleshooting this issue via policy trace debug and PCAP, we see the following information
connection: service.name=HTTP client.address=172.21.75.71 proxy.port=8080 source.port=59280 dest.port=8080 client.interface=2:1.746 routing-domain=default
location-id=0 access_type=unknown
time: 2021-11-02 12:08:36 UTC
unknown <invalid request url>
user: unauthenticated
authentication status='not_attempted' authorization status='not_attempted'
EXCEPTION(invalid_request): Request could not be handled
Last Error: URL could not be parsed for matching purposes '' failed because: Scheme was not delimited by '://'
server.response.code: 0
client.response.code: 400
application.name: unavailable
application.operation: unavailable
application.group: unavailable
DSCP client outbound: 65
DSCP server outbound: 65
Transaction timing: total-transaction-time 1 ms
Checkpoint timings:
new-connection: start 1 elapsed 0 ms
client-out-terminated: start 1 elapsed 0 ms
access-logging: start 1 elapsed 0 ms
stop-transaction: start 1 elapsed 0 ms
Total Policy evaluation time: 0 ms
url_categorization not completed
client connection: first-response-byte 0 last-response-byte 1
stop transaction --------------------
start transaction -------------------
transaction ID=3399355669 type=http.proxy
What we see in the policy trace debug is an exact match with the capture seen in the PCAP and it goes on, in cycles (loop), as the 172.21.75.71 sends the web request, for the "Unknown URL" to the Proxy (172.21.46.25).
We see, from the policy trace, that the web request from the 172.21.75.71 reached the ProxySG appliance (172.21.46.25) with an unknown URL, as seen in the trace.
This returned the "(invalid_request): Request could not be handled" exception, with the eventual "400" client response code.
The root cause is also seen in the trace, which is " Last Error: URL could not be parsed for matching purposes '' failed because: Scheme was not delimited by '://'".
Looking at the checkpoint timings for the transaction [1], we do not see the usual "client-in: start x elapsed y ms":
client-in: start 2 elapsed 104 ms ; Sample from other policy trace showing that the client started sending data at t+2ms in and finished a t+104ms
Rather we see:
client-out-terminated: start 1 elapsed 0 ms
The Proxy never received a URL request from the client, even though it received TCP connections from the client that should have formed a CONNECT request.
Because of the invalid URL, lacking the "://", ProxySG returns the "400" response code to the client.
That's exactly the same behaviour seen in the PCAP stream. After the ProxySG appliance, in frame 5, sends the last ACK, to complete the TCP handshake, it expected a HTTP CONNECT request in frame 6. That did not happen because of the invalid URL. With that, in frame 7, the ProxySG appliance sends a FIN ACK, to request the termination of the packet. In frame 8, the client machine resets the connection.
Significantly, because of the invalid URL request, URL categorization/policy evaluation did not happen and that's why we can see a large amount of "late" tags in the policy trace.
Note: The late tag [2] in a policy trace means that the ProxySG appliance reached a verdict on the connection before it could evaluate the policy rules that otherwise would have been evaluated later in the connection. See Tech. Doc. with URL below. The late tag appeared multiple times in a policy trace because the ProxySG appliance terminated the transaction early in (before) the evaluation. In this case, all of the policy rules that were not evaluated are considered late. This went on, in cycles (loops), in the policy trace, just as seen in the PCAP.
From the logs, we see, clearly, that the web requests failed not because of the web request but because of the invalid request, with an invalid URL, sent by the client.