Gathering HAProxy Ingress Access Logs and how to analyze them
What is HAProxy Ingress Access Logging?
Ingress Access Logging are records for client sessions and requests that are generated by HAProxy when the session completes. These logs are useful for troubleshooting connection and networking issues in the cluster for OpenShift or user applications. Considering HAProxy is a middle point proxying the traffic, access logs can be helpful in determing traffic behavior or assessing whether traffic is reaching HAProxy at all.
Ingress Access Logging is not enabled by default in OpenShift. This is because enabling Access Logging will put extra load on the router-default pods as it generates the pod with another container. You can also choose to send the logs to a syslog endpoint and forgo adding another container. If you are worried about the extra load it can cause. It's better to enable it on a 'need now' basis when troubleshooting an issue and having it disabled normally.
How to enable HAProxy Ingress Access Logs?
To enable Ingress access logging you can follow our documentation.
The easiest method is to send the traffic to a sidecar container within the OpenShift Ingress router pods for a given Ingresscontroller. You may add the following lines to the ingresscontroller object which will trigger a rollout of the router pods in openshift-ingress with a sidecar to capture this data:
$ oc get ingresscontroller -n openshift-ingress-operator
NAME AGE
default 37h
$ oc edit ingresscontroller/default -n openshift-ingress-operator
apiVersion: operator.openshift.io/v1
kind: IngressController
metadata:
name: default
namespace: openshift-ingress-operator
spec:
logging: #<--
access: #<--
destination: #<--
type: Container #<-- add these lines and save the file
clientTLS:
clientCA:
name: ""
clientCertificatePolicy: ""
defaultCertificate:
name: ssl-cert
httpCompression: {}
httpEmptyRequestsPolicy: Respond
httpErrorCodePages:
name: ""
idleConnectionTerminationPolicy: Deferred
replicas: 2
tuningOptions:
reloadInterval: 0s
unsupportedConfigOverrides: null
Once the file is saved, you will observe the router-default pods doing a graceful shutdown + being replaced by new router pods with the sidecar enabled, which will stabilize after a few minutes (router pods have a lengthy graceful stop window of 2m).
oc get pod -n openshift-ingress
NAME READY STATUS RESTARTS AGE
router-default-7fd4dcf986-jkljb 1/1 Terminating 0 37h
router-default-7fd4dcf986-m45xb 0/1 Terminating 0 3h4m
router-default-bd87bfb5f-dmkj7 2/2 Running 0 39s
router-default-bd87bfb5f-sgkqz 0/2 Pending 0 6s
Access logs capture data starting from the time they are enabled - they cannot retroactively log past connections. Once enabled, you will need to replicate the behavior again (curling a route, or visiting a webpage) to capture the data in the logs for subsequent analysis.
If supplying data to Red Hat for review, ensure you capture relevant timecodes, source IP information and the route you are calling. You can capture a namespace inspect for offline analysis (and to preserve logs) with the following command:
$ oc adm inspect namespace openshift-ingress <optional-additional-namespaces-here> - It may be helpful to include an inspect of the project where the route you are investigating is managed, so that relevant application logs, IP addresses and timecodes can be correlated for easier analysis.
How to read HAProxy Ingress Access Logs
Enabling Access logs on the ingresscontroller resource will generate a rollout of the router pods. You may need to wait a bit for logs to be generated as logs are only generated once the connection is complete. You can view logs in the 'logs' container of the router pod if you are logging to a container or your syslog server is sending them to syslog.
$ oc logs router-default-xxxxx-xxxx -c logs -n openshift-ingress
The logs by default are formatted in Content from www.haproxy.com is not included.HTTP log format. Unless it is a TCP connection in which case the log entry will be generated in Content from www.haproxy.com is not included.TCP log format. There are multiple log formats that HAProxy can use but currently OpenShift only supports the TCP and HTTP log format and you can only customize the HTTP log format in OpenShift. There is an This content is not included.RFE:3811 opened to support more log format types but it has not been accepted currently.
Here is an example HTTP connection in HAProxy access log format.
2023-11-21T17:00:42.174408+00:00 router-default-6fddd96bd5-w776r router-default-6fddd96bd5-w776r haproxy[43]: xx.xx.xx.xxx:51098 [21/Nov/2023:17:00:42.161] fe_sni~ be_secure:openshift-console:console/pod:console-xxxxxx-xxxxx:console:https:xxx.xx.x.xx:8443 0/0/0/12/12 200 661 - - --VN 158/18/16/14/0 0/0 {1wt.eu} {} "GET /api/prometheus-tenancy/api/v1/query_range?start=1700582441.997&end=1700586041.997&step=60&namespace=openshift-ingress&query=count%28kube_running_pod_ready%7Bnamespace%3D%27openshift-ingress%27%7D%29+BY+%28namespace%29 HTTP/1.1"
Lets split access log into different fields and go through them one by one.
Field Example from Above
----- ------------------
Recorded Log time 2023-11-21T17:00:42.174408+00:00
Hit Router Pod router-default router-default
Process Name haproxy[43]
Client IP, Client Port xx.xx.xx.xxx:51098
Request Date [21/Nov/2023:17:00:42.161]
Frontend name fe_sni~
Backend name/ Server Name be_secure:openshift-console:console/pod:console-xxxxxx-
xxxxx:console:https:xxx.xx.x.xx:8443
TR '/' Tw '/' Tc '/' Tr '/' Ta* 0/0/0/12/12
Status Code 200
bytes_read* 661
Captured Request Cookie -
Captured Response Cookie -
Termination State --VN
actconn '/' feconn '/'beconn '/' srv_conn '/' retries* 158/18/16/14/0
srv_queue '/' backend_queue 0/0
Captured Request Header {1wt.eu}
Response Request Header {}
'"' http_request '"' "GET /api HTTP/1.1"
Note: That some fields will not be present in a log entry. Such as Request Headers or http_request if the traffic does not have any data set in that field.
Defining each Field and using it for troubleshooting
Lets go through each Field in more detail
- Recorded Log time: Time when the router logged the connection
- Hit Router pod: The router pod that was involved in the connection
- Process Name: The HAProxy pid involved in the connection
- Client IP, Client Port: The client ip and tcp port that initiated the connection. Note that if an intermediary service is forwarding the connection to HAProxy and is not using PROXY protocol then the client IP will be set to the loadbalancer instead of the actual client.
- Request Date: The time and date the first bye of the request was received by HAProxy
- Frontend name: Name of the frontend that received the connection
- Backend name: Name of the backend that was selected to manage the connection
- Server name: Name of the last server the connection was sent to. This server belongs to the backend that handles the request. If the connection was aborted before completion a NOSRV is indicated
- TR: The total time in milliseconds spent waiting for the full HTTP request from the client. This time starts after the first byte is received. A large value could be indicative of network issues or latency. A value of -1 indicates the connection was aborted
- Tw: Total time in milliseconds spent waiting in various queues. Value of -1 indicates connection was aborted
- Tc: Total time in milliseconds spent waiting for connection to establish to final server including retries. A value of -1 indicates connection was aborted
- Tr: Total time in milliseconds spent waiting for the server to send a full HTTP response. A value of -1 indicates a connection was aborted. Generally matches the servers processing time.
- Ta: Time the request remains active in HAProxy. Total time elapsed between when the first byte is received and when is the last byte is received. Covers all processing time except handshake and idle time.
- Status Code: The HTTP status code returned to the client. Generally set by the server but if the server is unreachable can be set by HAProxy. Each exit code has a special meaning and you may Content from docs.haproxy.org is not included.refer to the upstream documentation on these codes to learn more about them.
- bytes_read: Total number of bytes transmitted to the client when the log is emitted. Does not include HTTP Headers
- Captured Request Header: Optional "name=value" entry indicating that a cookie is captured in this session. Only one cookie can be captured. Used for session tracking
- Captured Response Header: Optional "name=value" entry indicating that the server returned a cookie. Only one cookie can be captured. Used for session tracking
- Content from www.haproxy.com is not included.Termination State: Condition the session was in when it was ending, indicates session state, which side ended the session and the reason
- actconn: Total number of concurrent connections happening when the connection was logged. Useful when determining if a connection limit is being reached
- feconn: Total number of concurrent connections happening on the frontend when the connection was logged. Useful for determining resources and frontend max connections
- beconn: Total number of concurrent connections happening on the backend when the connection was logged. Includes current and pending connections. If this values has huge jumps the backend servers may be overloaded
- srv_conn: Total number of concurrent connections still active when the connection was logged. Can never exceed the servers maxconn value.
- retries : Number of connection retries experienced by this session when trying to connect to a server. Should normally be 0 any amount higher could indicate network issues
- srv-queue: Total number of requests which were processed before this one in the server queue. It is 0 when the request has not gone through the server queue
- backend_queue: is the total number of requests which were processed before this one in the backend's global queue. It is zero when the request has not gone through the global queue.
- Captured Request Headers: A list of headers captured in the request due to the presence of a 'capture request header' statement. Will be delimited by vertical bars. (|) When no capture is requested the braces do not appear.
- Captured Response Headers: A list of headers captured in the response due to the presence of a 'capture response header' statement. Will be delimited by vertical bars. (|) When no capture is requested the braces do not appear.
- http_request: The complete HTTP request line, including the method, request, and the HTTP string. This is always the last field even if new fields are added.
It is also possible to add additional values by defining it in the httpLogFormat: yaml for the ingresscontroller
apiVersion: operator.openshift.io/v1
kind: IngressController
metadata:
name: default
namespace: openshift-ingress-operator
spec:
replicas: 2
logging:
access:
destination:
type: Syslog
syslog:
address: 1.2.3.4
port: 10514
httpLogFormat: '%ci:%cp [%t] %ft %b/%s %B %bq %HM %HU %HV'
These options do the following
%ci - Client IP address
%cp - Client port
[%t] - Time in the format of YYYY-MM-DDTHH:MM:SS.ssssss+ZZ:ZZ
%ft - Frontend name
%b/%s - Bytes read from client/server
%B - Bytes sent to client (excluding HTTP headers)
%bq - Bytes in request header
%HM - HTTP method
%HU - URL path
%HV - HTTP version
If you want a more detailed explanation for every field or other log formats that OpenShift does not support. You can read the Content from www.haproxy.com is not included.HAProxy Configuration Manual.. Another example of custom httpLogFormat can be seen in this solution
Route Types and how they affect HAProxy Logging
There are three route types available in OpenShift: Edge, re-encrypt, and passthrough. Each of these three routes types define where encryption will be terminated. They also determine how the backend will be configured in HAProxy
- Edge: Terminates encryption at HAProxy and is sent unencrypted to the backend
- Re-encrypt: Terminates encryption at HAProxy and is then re-encrypted by HAProxy before being sent to the backend
- Passthrough: Does not terminate encryption at HAProxy and remains encrypted until it reaches the server where it is then de-encrypted.
HAproxy will use Server Name Indication (SNI) with any encrypted connection because the HAProxy frontend has to determine how to handle the packet based on the SNI regardless if it is edge, re-encrypt, or pass through:
When a route is created, depending on the route type. The backend will change.
1. If termination is not set: This is plain http -> http. Create a be_http:<service> backend.
Incoming http traffic is terminated and sent as http to the pods.
2. If termination is type 'edge': This is https -> http. Create a be_edge_http:<service> backend.
Incoming https traffic is terminated and sent as http to the pods.
3. If termination is type 'reencrypt': This is https -> https. Create a be_secure:<service> backend.
Incoming https traffic is terminated and then sent as https to the pods.
4. If termination is type 'passthrough': This is https (or any SNI TLS connection) passthrough.
Create a be_tcp:<service> backend.
Incoming traffic is inspected to get the hostname from the SNI header, but then all traffic is
passed through to the backend pod by just looking at the TCP headers.
You can look at how HAProxy will set the frontend and backend for routes by referencing this Content from github.com is not included.github code.
Other logs found in HAProxy Access Logging
When looking through HAProxy logs you may see the following logs
2024-02-18T20:51:22.129159671Z 2024-02-18T20:51:22.128842+00:00 xxx-xxxx-xxx4-xx-2xxx-infra-xxxxx xxx-xxxx-xxx4-xx-2xxx-infra-xxxxx haproxy[31]: Proxy public started.
2024-02-18T20:51:27.145102052Z 2024-02-18T20:51:27.145072+00:00 xxx-xxxx-xxx4-xx-2xxx-infra-xxxxx xxx-xxxx-xxx4-xx-2xxx-infra-xxxxx haproxy[33]: Stopping backend be_secure:openshift-user-workload-monitoring:thanos-ruler in 0 ms.
2024-02-18T20:51:27.145254367Z 2024-02-18T20:51:27.145229+00:00 xxx-xxxx-xxx4-xx-2xxx-infra-xxxxx xxx-xxxx-xxx4-xx-2xxx-infra-xxxxx haproxy[33]: Proxy be_edge_http:app-prereq-validation:external-connectivity stopped (cumulated conns: FE
: 0, BE: 0).
These are the administrative logs for the backend and frontends that HAProxy has configured. The frontend and backend routes are starting and stopping every time HAProxy is reloading.
Useful documentation
- The Content from www.haproxy.com is not included.HAProxy configuration manual.
- The Content from www.haproxy.com is not included.HAProxy access logging documentation.
- The Content from github.com is not included.OpenShift router code