How-to leverage SWG access log info to troubleshoot web server side related issues, in particular latency
Article ID: 280074
Updated On:
Products
Issue/Introduction
Customise SWG access log to get useful info to troubleshoot web server side related issues
Resolution
Access log fields or better "ProxySG Log Fields and Substitutions" have not changed so often in the past but new ones have been introduced in newer SGOS versions.
We may refer to SGOS admin manual chapters/fields tables:
time-taken = Time taken (in milliseconds) to process the request (from the first byte of client request data received by the proxy, to the last byte sent by the proxy to the client, including all of the delays by ICAP, and so on).
connect-time = Total ms required to connect to the OCS
x-bluecoat-authentication-time = Time (ms) required to authenticate the user
cs-categorization-time = Time taken (in milliseconds) to categorize the request URL
cs-categorization-time-dynamic = Time taken (in milliseconds) to dynamically categorize the request URL
cs-categorization-time-static = Time taken (in milliseconds) to statically categorize the request URL
cs-request-time = Time taken (in milliseconds) between NC and CI checkpoints
dnslookup-time = Total ms cache required to perform the DNS lookup
x-client-dnslookup-time = Total time taken (in ms) to perform the client DNS lookup. (7.4.2.1 7.3.2.1 6.7.5.8)
x-server-dnslookup-time = Total time taken (in ms) to perform the server DNS lookup. (7.4.2.1 7.3.2.1 6.7.5.8)
duration = Time taken, in seconds, to process the request
rs-download-time-taken = Total time taken (in milliseconds) to receive the complete response from the origin content server
rs-service-latency = Total ms required to connect and receive first response byte from the origin server
rs-service-time-taken = Total time taken (in milliseconds) to receive the first response byte from the origin content server.
rs-time-taken = Total time taken (in milliseconds) to send the request and receive the response from the origin server
sc-time-taken = Total time taken (in milliseconds) to return the response to the client
x-bluecoat-total-policy-evaluation-time = Total time spent evaluating policy for this transaction
x-bluecoat-icap-reqmod-delay-time = Time taken (in milliseconds) to connect to ICAP REQMOD service
x-bluecoat-icap-reqmod-queuing-time = Time spent waiting (in milliseconds) for a queuing ICAP REQMOD service
x-bluecoat-icap-reqmod-service-time = Time taken (in milliseconds) for ICAP REQMOD service once connected
x-bluecoat-icap-reqmod-setup-time = Time spent waiting (in milliseconds) to set up the ICAP REQMOD service
x-bluecoat-icap-respmod-delay-time = Time taken (in milliseconds) to connect to ICAP RESPOD service
x-bluecoat-icap-respmod-queuing-time = Time spent waiting (in milliseconds) for a queuing ICAP RESPMOD service
x-bluecoat-icap-respmod-service-time = Time taken (in milliseconds) for ICAP RESPMOD service once connected
x-bluecoat-icap-respmod-setup-time = Time spent waiting (in milliseconds) to set up the ICAP RESPMOD service
x-bluecoat-request-latency = Time from CI start to server connection start
x-bluecoat-response-first-byte-latency = Time from first response byte received from server to first response byte sent to client
x-bluecoat-response-last-byte-latency = Time from last response byte received from server to last response byte sent to client
x-bluecoat-total-time-added = Total of request latency and response latency to last byte
x-cs-https-handshake-time = Total time taken (in ms) to complete the HTTPS handshake of the downstream connection. (7.4.2.1 6.7.5.8)
x-sr-https-handshake-time = Total time taken (in ms) to complete the HTTPS handshake of the upstream connection. (7.2.4.1 6.7.5.8)
* * * * * * *
The full access log fields list can also be found in article ID: 240610 - "Edge SWG (ProxySG) Access Log Fields".
Practical how-to steps:
1) Use the default current SGOS "main" access log fields list as base, and then add upstream server latency useful fields picking them from the above list
2) Create a customised log format, example:
"date time time-taken c-ip sc-status s-action sc-bytes cs-bytes cs-method cs-uri-scheme cs-host cs-uri-port cs-uri-path cs-uri-query cs-username cs-auth-group s-supplier-name s-supplier-ip s-supplier-country s-supplier-failures rs(Content-Type) cs(Referer) cs(User-Agent) sc-filter-result cs-categories x-virus-id s-ip cs-threat-risk x-bluecoat-transaction-uuid x-icap-reqmod-header(X-ICAP-Metadata) x-icap-respmod-header(X-ICAP-Metadata) connect-time x-bluecoat-authentication-time cs-categorization-time cs-categorization-time-dynamic cs-categorization-time-static cs-request-time dnslookup-time x-client-dnslookup-time x-server-dnslookup-time duration rs-download-time-taken rs-service-latency rs-service-time-taken rs-time-taken sc-time-taken x-bluecoat-total-policy-evaluation-time x-bluecoat-icap-reqmod-delay-time x-bluecoat-icap-reqmod-queuing-time x-bluecoat-icap-reqmod-service-time x-bluecoat-icap-reqmod-setup-time x-bluecoat-icap-respmod-delay-time x-bluecoat-icap-respmod-queuing-time x-bluecoat-icap-respmod-service-time x-bluecoat-icap-respmod-setup-time x-bluecoat-request-latency x-bluecoat-response-first-byte-latency x-bluecoat-response-last-byte-latency x-bluecoat-total-time-added x-cs-https-handshake-time x-sr-https-handshake-time"
3) Create a new access log setting the customised format, example:
4) Above log is made of about 60 fields and can grow quite fast in a busy production environment. We would suggest "trigger" it thanks to CPL policies only temporary while troubleshooting. You may setup the "Upload Client" to send the data to your access log repository or leave it locally (in the SWG)
5) Set a test client specific policy to get above "verbose" access log taken only for a specific client IP, example:
<Proxy>
client.address=10.10.10.3/32 access_log[logToDebugOCSlatency](yes)
6) Analyse the collected access log data either locally, pulling live data from SGOS advance URL, example "https://SWG.local:8082/Accesslog/tail-f/logToDebugOCSlatency" or in access log repository where they were sent
Example client reaching out for "example.com":
-
XXXX-02-28 09:15:17 124 10.0.200.1 200 TCP_MISS 284861 679 GET https example.com 443 /static-assets/image/pages/home/devices/how-it-works/desktop/web-protection-front-light.png - testuser -
example.com 40.114.177.156 "Netherlands" - image/png https://example.com/ "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
PROXIED "Search Engines/Portals" - 10.0.80.80 2 f454a9c809b1f5c5-000000000006e93f-0000000065def9a4 - "{ "expect_sandbox": false }" 0 - 2 - 2 1 0 0 0 0 90 29 29 119 0 0 - - - - 0 - 84 0 0 93 3 3 - - -
XXXX-02-28 09:15:17 133 10.0.200.1 200 TCP_MISS 491805 669 GET https example.com 443 /static-assets/image/pages/home/devices/how-it-works/web-protection-ios-light.png - testuser -
example.com 40.114.177.156 "Netherlands" - image/png https://example.com/ "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
PROXIED "Search Engines/Portals" - 10.0.80.80 2 f454a9c809b1f5c5-000000000006e939-0000000065def9a4 - "{ "expect_sandbox": false }" 0 - 1 - 1 0 0 0 0 0 97 29 29 126 1 0 - - - - 0 - 101 0 1 101 5 6 - - -
XXXX-02-28 09:15:17 159 10.0.200.1 200 TCP_MISS 39934 681 GET https example.com 443 /static-assets/image/pages/home/devices/how-it-works/desktop/email-protection-front-light.png - testuser -
example.com 40.114.177.156 "Netherlands" - image/png https://example.com/ "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
PROXIED "Search Engines/Portals" - 10.0.80.80 2 f454a9c809b1f5c5-000000000006e93e-0000000065def9a4 - "{ "expect_sandbox": false }" 0 - 0 - 0 0 0 0 0 0 9 29 29 38 0 0 - - - - 0 - 120 1 0 129 120 120 - - -
XXXX-02-28 09:15:17 72 10.0.200.1 200 TCP_MISS 5216 600 GET https example.com 443 /favicon.ico - testuser -
example.com 40.114.177.156 "Netherlands" - image/x-icon https://example.com/ "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36"
PROXIED "Search Engines/Portals" - 10.0.80.80 2 f454a9c809b1f5c5-000000000006e94f-0000000065def9a5 - "{ "expect_sandbox": false }" 0 - 1 - 1 0 0 0 0 0 0 65 65 65 0 0 - - - - 0 - 6 0 0 6 6 6 - - - date time time-taken c-ip sc-status
s-action --> TCP_MISS
sc-bytes cs-bytes cs-method cs-uri-scheme
cs-host --> example.com
cs-uri-port cs-uri-path cs-uri-query cs-username cs-auth-group s-supplier-name s-supplier-ip s-supplier-country
s-supplier-failures rs(Content-Type) cs(Referer) cs(User-Agent) sc-filter-result cs-categories x-virus-id s-ip cs-threat-risk x-bluecoat-transaction-uuid x-icap-reqmod-header(X-ICAP-Metadata)
x-icap-respmod-header(X-ICAP-Metadata) --> 0
connect-time --> -
x-bluecoat-authentication-time --> 1
cs-categorization-time --> -
cs-categorization-time-dynamic --> 1
cs-categorization-time-static --> 0
cs-request-time --> 0
dnslookup-time --> 0
x-client-dnslookup-time --> 0
x-server-dnslookup-time duration --> 0
rs-download-time-taken --> 0
rs-service-latency --> 65
rs-service-time-taken --> 65
rs-time-taken --> 65
sc-time-taken --> 0
x-bluecoat-total-policy-evaluation-time --> 0
x-bluecoat-icap-reqmod-delay-time --> -
x-bluecoat-icap-reqmod-queuing-time --> -
x-bluecoat-icap-reqmod-service-time --> -
x-bluecoat-icap-reqmod-setup-time --> -
x-bluecoat-icap-respmod-delay-time --> 0
x-bluecoat-icap-respmod-queuing-time --> -
x-bluecoat-icap-respmod-service-time --> 6
x-bluecoat-icap-respmod-setup-time --> 0
x-bluecoat-request-latency --> 0
x-bluecoat-response-first-byte-latency --> 6
x-bluecoat-response-last-byte-latency --> 6
x-bluecoat-total-time-added --> 6
x-cs-https-handshake-time --> -
x-sr-https-handshake-time --> -
It is important to highlight:
a) If the requested object was found in the cache of the SWG there will be no much data exchanged with the web-server. It is better to include in the log "s-action" that shows the "type of action the appliance took to process this request; possible values include ALLOWED, DENIED, FAILED, SERVER_ERROR" but also:
- TCP_MISS - Object not found in cache, downloaded from the OCS.
- TCP_HIT - Object found in cache.
- TCP_NC_MISS - The request was made for an object that can't be cached.
- TCP_REFRESH_MISS - Appliance had the object in cache, but a check with the OCS (GET with the If-modified-since) indicated that the object was stale. Object was downloaded from the OCS and the new object was placed in cache.
b) Modern website, web applications to function need the client to download many objects from many sources (content delivery networks), therefore the access log analysis should be carried out for every file/object the client requested from any domain/public IP to build the webpage
Feedback
