8. Logging
One of HAProxy’s strong points certainly lies is its precise logs. It probably provides the finest level of information available for such a product, which is very important for troubleshooting complex environments. Standard information provided in logs include client ports, TCP/HTTP state timers, precise stream state at termination and precise termination cause, information about decisions to direct traffic to a server, and of course the ability to capture arbitrary headers.
In order to improve administrators reactivity, it offers a great transparency about encountered problems, both internal and external, and it is possible to send logs to different sources at the same time with different level filters:
- global process-level logs (system errors, start/stop, etc..)
- per-instance system and internal errors (lack of resource, bugs, …)
- per-instance external troubles (servers up/down, max connections)
- per-instance activity (client connections), either at the establishment or at the termination.
- per-request control of log-level, e.g. http-request set-log-level silent if sensitive_request
The ability to distribute different levels of logs to different log servers allow several production teams to interact and to fix their problems as soon as possible. For example, the system team might monitor system-wide errors, while the application team might be monitoring the up/down for their servers in real time, and the security team might analyze the activity logs with one hour delay.
8.1. Log levels
TCP and HTTP connections can be logged with information such as the date, time, source IP address, destination address, connection duration, response times, HTTP request, HTTP return code, number of bytes transmitted, conditions in which the stream ended, and even exchanged cookies values. For example track a particular user’s problems. All messages may be sent to up to two syslog servers. Check the “log” keyword in section 4.2 for more information about log facilities.
8.2. Log formats
HAProxy supports 5 log formats. Several fields are common between these formats and will be detailed in the following sections. A few of them may vary slightly with the configuration, due to indicators specific to certain options. The supported formats are as follows:
the default format, which is very basic and very rarely used. It only provides very basic information about the incoming connection at the moment it is accepted: source IP:port, destination IP:port, and frontend-name. This mode will eventually disappear so it will not be described to great extents.
the TCP format, which is more advanced. This format is enabled when “option tcplog” is set on the frontend. HAProxy will then usually wait for the connection to terminate before logging. This format provides much richer information, such as timers, connection counts, queue size, etc… This format is recommended for pure TCP proxies.
the HTTP format, which is the most advanced for HTTP proxying. This format is enabled when “option httplog” is set on the frontend. It provides the same information as the TCP format with some HTTP-specific fields such as the request, the status code, and captures of headers and cookies. This format is recommended for HTTP proxies.
the CLF HTTP format, which is equivalent to the HTTP format, but with the fields arranged in the same order as the CLF format. In this mode, all timers, captures, flags, etc… appear one per field after the end of the common fields, in the same order they appear in the standard HTTP format.
the custom log format, allows you to make your own log line.
Next sections will go deeper into details for each of these formats. Format specification will be performed on a “field” basis. Unless stated otherwise, a field is a portion of text delimited by any number of spaces. Since syslog servers are susceptible of inserting fields at the beginning of a line, it is always assumed that the first field is the one containing the process name and identifier.
Note: Since log lines may be quite long, the log examples in sections below might be broken into multiple lines. The example log lines will be prefixed with 3 closing angle brackets (’>>>’) and each time a log is broken into multiple lines, each non-final line will end with a backslash (’\’) and the next line will start indented by two characters.
8.2.1. Default log format
This format is used when no specific option is set. The log is emitted as soon as the connection is accepted. One should note that this currently is the only format which logs the request’s destination IP and ports.
Example:
Field Format Extract from the example above 1 process_name ‘[’ pid ‘]:’ haproxy[14385]: 2 ‘Connect from’ Connect from 3 source_ip ‘:’ source_port 10.0.1.2:33312 4 ’to’ to 5 destination_ip ‘:’ destination_port 10.0.3.31:8012 6 ‘(’ frontend_name ‘/’ mode ‘)’ (www/HTTP)
Detailed fields description:
- “source_ip” is the IP address of the client which initiated the connection.
- “source_port” is the TCP port of the client which initiated the connection.
- “destination_ip” is the IP address the client connected to.
- “destination_port” is the TCP port the client connected to.
- “frontend_name” is the name of the frontend (or listener) which received and processed the connection.
- “mode is the mode the frontend is operating (TCP or HTTP).
In case of a UNIX socket, the source and destination addresses are marked as “unix:” and the ports reflect the internal ID of the socket which accepted the connection (the same ID as reported in the stats).
It is advised not to use this deprecated format for newer installations as it will eventually disappear.
8.2.2. TCP log format
The TCP format is used when “option tcplog” is specified in the frontend, and is the recommended format for pure TCP proxies. It provides a lot of precious information for troubleshooting. Since this format includes timers and byte counts, the log is normally emitted at the end of the session. It can be emitted earlier if “option logasap” is specified, which makes sense in most environments with long sessions such as remote terminals. Sessions which match the “monitor” rules are never logged. It is also possible not to emit logs for sessions for which no data were exchanged between the client and the server, by specifying “option dontlognull” in the frontend. Successful connections will not be logged if “option dontlog-normal” is specified in the frontend.
The TCP log format is internally declared as a custom log format based on the exact following string, which may also be used as a basis to extend the format if required. Additionally the HAPROXY_TCP_LOG_FMT variable can be used instead. Refer to section 8.2.6 “Custom log format” to see how to use this:
And the CLF log format is internally declared as a custom log format based on this exact string:
A few fields may slightly vary depending on some configuration options, those are marked with a star (’*’) after the field name below.
Example:
Field Format Extract from the example above 1 process_name ‘[’ pid ‘]:’ haproxy[14387]: 2 client_ip ‘:’ client_port 10.0.1.2:33313 3 ‘[’ accept_date ‘]’ [06/Feb/2009:12:12:51.443] 4 frontend_name fnt 5 backend_name ‘/’ server_name bck/srv1 6 Tw ‘/’ Tc ‘/’ Tt* 0/0/5007 7 bytes_read* 212 8 termination_state – 9 actconn ‘/’ feconn ‘/’ beconn ‘/’ srv_conn ‘/’ retries* 0/0/0/0/3 10 srv_queue ‘/’ backend_queue 0/0
Detailed fields description:
“client_ip” is the IP address of the client which initiated the TCP connection to HAProxy. If the connection was accepted on a UNIX socket instead, the IP address would be replaced with the word “unix”. Note that when the connection is accepted on a socket configured with “accept-proxy” and the PROXY protocol is correctly used, or with a “accept-netscaler-cip” and the NetScaler Client IP insertion protocol is correctly used, then the logs will reflect the forwarded connection’s information.
“client_port” is the TCP port of the client which initiated the connection. If the connection was accepted on a UNIX socket instead, the port would be replaced with the ID of the accepting socket, which is also reported in the stats interface.
“accept_date” is the exact date when the connection was received by HAProxy (which might be very slightly different from the date observed on the network if there was some queuing in the system’s backlog). This is usually the same date which may appear in any upstream firewall’s log. When used in HTTP mode, the accept_date field will be reset to the first moment the connection is ready to receive a new request (end of previous response for HTTP/1, immediately after previous request for HTTP/2).
“frontend_name” is the name of the frontend (or listener) which received and processed the connection.
“backend_name” is the name of the backend (or listener) which was selected to manage the connection to the server. This will be the same as the frontend if no switching rule has been applied, which is common for TCP applications.
“server_name” is the name of the last server to which the connection was sent, which might differ from the first one if there were connection errors and a redispatch occurred. Note that this server belongs to the backend which processed the request. If the connection was aborted before reaching a server, “
<NOSRV>” is indicated instead of a server name.“Tw” is the total time in milliseconds spent waiting in the various queues. It can be “-1” if the connection was aborted before reaching the queue. See “Timers” below for more details.
“Tc” is the total time in milliseconds spent waiting for the connection to establish to the final server, including retries. It can be “-1” if the connection was aborted before a connection could be established. See “Timers” below for more details.
“Tt” is the total time in milliseconds elapsed between the accept and the last close. It covers all possible processing. There is one exception, if “option logasap” was specified, then the time counting stops at the moment the log is emitted. In this case, a ‘+’ sign is prepended before the value, indicating that the final one will be larger. See “Timers” below for more details.
“bytes_read” is the total number of bytes transmitted from the server to the client when the log is emitted. If “option logasap” is specified, the this value will be prefixed with a ‘+’ sign indicating that the final one may be larger. Please note that this value is a 64-bit counter, so log analysis tools must be able to handle it without overflowing.
“termination_state” is the condition the session was in when the session ended. This indicates the session state, which side caused the end of session to happen, and for what reason (timeout, error, …). The normal flags should be “–”, indicating the session was closed by either end with no data remaining in buffers. See below “Stream state at disconnection” for more details.
“actconn” is the total number of concurrent connections on the process when the session was logged. It is useful to detect when some per-process system limits have been reached. For instance, if actconn is close to 512 when multiple connection errors occur, chances are high that the system limits the process to use a maximum of 1024 file descriptors and that all of them are used. See section 3 “Global section” to find how to tune the system.
“feconn” is the total number of concurrent connections on the frontend when the session was logged. It is useful to estimate the amount of resource required to sustain high loads, and to detect when the frontend’s “maxconn” has been reached. Most often when this value increases by huge jumps, it is because there is congestion on the backend servers, but sometimes it can be caused by a denial of service attack.
“beconn” is the total number of concurrent connections handled by the backend when the session was logged. It includes the total number of concurrent connections active on servers as well as the number of connections pending in queues. It is useful to estimate the amount of additional servers needed to support high loads for a given application. Most often when this value increases by huge jumps, it is because there is congestion on the backend servers, but sometimes it can be caused by a denial of service attack.
“srv_conn” is the total number of concurrent connections still active on the server when the session was logged. It can never exceed the server’s configured “maxconn” parameter. If this value is very often close or equal to the server’s “maxconn”, it means that traffic regulation is involved a lot, meaning that either the server’s maxconn value is too low, or that there aren’t enough servers to process the load with an optimal response time. When only one of the server’s “srv_conn” is high, it usually means that this server has some trouble causing the connections to take longer to be processed than on other servers.
“retries” is the number of connection retries experienced by this session when trying to connect to the server. It must normally be zero, unless a server is being stopped at the same moment the connection was attempted. Frequent retries generally indicate either a network problem between HAProxy and the server, or a misconfigured system backlog on the server preventing new connections from being queued. This field may optionally be prefixed with a ‘+’ sign, indicating that the session has experienced a redispatch after the maximal retry count has been reached on the initial server. In this case, the server name appearing in the log is the one the connection was redispatched to, and not the first one, though both may sometimes be the same in case of hashing for instance. So as a general rule of thumb, when a ‘+’ is present in front of the retry count, this count should not be attributed to the logged server.
“srv_queue” is the total number of requests which were processed before this one in the server queue. It is zero when the request has not gone through the server queue. It makes it possible to estimate the approximate server’s response time by dividing the time spent in queue by the number of requests in the queue. It is worth noting that if a session experiences a redispatch and passes through two server queues, their positions will be cumulative. A request should not pass through both the server queue and the backend queue unless a redispatch occurs.
“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. It makes it possible to estimate the average queue length, which easily translates into a number of missing servers when divided by a server’s “maxconn” parameter. It is worth noting that if a session experiences a redispatch, it may pass twice in the backend’s queue, and then both positions will be cumulative. A request should not pass through both the server queue and the backend queue unless a redispatch occurs.
8.2.3. HTTP log format
The HTTP format is the most complete and the best suited for HTTP proxies. It is enabled by when “option httplog” is specified in the frontend. It provides the same level of information as the TCP format with additional features which are specific to the HTTP protocol. Just like the TCP format, the log is usually emitted at the end of the stream, unless “option logasap” is specified, which generally only makes sense for download sites. A stream which matches the “monitor” rules will never logged. It is also possible not to log streams for which no data were sent by the client by specifying “option dontlognull” in the frontend. Successful connections will not be logged if “option dontlog-normal” is specified in the frontend.
The HTTP log format is internally declared as a custom log format based on the exact following string, which may also be used as a basis to extend the format if required. Additionally the HAPROXY_HTTP_LOG_FMT variable can be used instead. Refer to section 8.2.6 “Custom log format” to see how to use this:
And the CLF log format is internally declared as a custom log format based on this exact string:
Most fields are shared with the TCP log, some being different. A few fields may slightly vary depending on some configuration options. Those ones are marked with a star (’*’) after the field name below.
Example:
Field Format Extract from the example above 1 process_name ‘[’ pid ‘]:’ haproxy[14389]: 2 client_ip ‘:’ client_port 10.0.1.2:33317 3 ‘[’ request_date ‘]’ [06/Feb/2009:12:14:14.655] 4 frontend_name http-in 5 backend_name ‘/’ server_name static/srv1 6 TR ‘/’ Tw ‘/’ Tc ‘/’ Tr ‘/’ Ta* 10/0/30/69/109 7 status_code 200 8 bytes_read* 2750 9 captured_request_cookie - 10 captured_response_cookie - 11 termination_state —- 12 actconn ‘/’ feconn ‘/’ beconn ‘/’ srv_conn ‘/’ retries* 1/1/1/1/0 13 srv_queue ‘/’ backend_queue 0/0 14 ‘{’ captured_request_headers* ‘}’ {haproxy.1wt.eu} 15 ‘{’ captured_response_headers* ‘}’ {} 16 ‘”’ http_request ‘"’ “GET /index.html HTTP/1.1”
Detailed fields description:
“client_ip” is the IP address of the client which initiated the TCP connection to HAProxy. If the connection was accepted on a UNIX socket instead, the IP address would be replaced with the word “unix”. Note that when the connection is accepted on a socket configured with “accept-proxy” and the PROXY protocol is correctly used, or with a “accept-netscaler-cip” and the NetScaler Client IP insertion protocol is correctly used, then the logs will reflect the forwarded connection’s information.
“client_port” is the TCP port of the client which initiated the connection. If the connection was accepted on a UNIX socket instead, the port would be replaced with the ID of the accepting socket, which is also reported in the stats interface.
“request_date” is the exact date when the first byte of the HTTP request was received by HAProxy (log field %tr).
“frontend_name” is the name of the frontend (or listener) which received and processed the connection.
“backend_name” is the name of the backend (or listener) which was selected to manage the connection to the server. This will be the same as the frontend if no switching rule has been applied.
“server_name” is the name of the last server to which the connection was sent, which might differ from the first one if there were connection errors and a redispatch occurred. Note that this server belongs to the backend which processed the request. If the request was aborted before reaching a server, “
<NOSRV>” is indicated instead of a server name. If the request was intercepted by the stats subsystem, “<STATS>” is indicated instead.“TR” is the total time in milliseconds spent waiting for a full HTTP request from the client (not counting body) after the first byte was received. It can be “-1” if the connection was aborted before a complete request could be received or a bad request was received. It should always be very small because a request generally fits in one single packet. Large times here generally indicate network issues between the client and HAProxy or requests being typed by hand. See section 8.4 “Timing Events” for more details.
“Tw” is the total time in milliseconds spent waiting in the various queues. It can be “-1” if the connection was aborted before reaching the queue. See section 8.4 “Timing Events” for more details.
“Tc” is the total time in milliseconds spent waiting for the connection to establish to the final server, including retries. It can be “-1” if the request was aborted before a connection could be established. See section 8.4 “Timing Events” for more details.
“Tr” is the total time in milliseconds spent waiting for the server to send a full HTTP response, not counting data. It can be “-1” if the request was aborted before a complete response could be received. It generally matches the server’s processing time for the request, though it may be altered by the amount of data sent by the client to the server. Large times here on “GET” requests generally indicate an overloaded server. See section 8.4 “Timing Events” for more details.
“Ta” is the time the request remained active in HAProxy, which is the total time in milliseconds elapsed between the first byte of the request was received and the last byte of response was sent. It covers all possible processing except the handshake (see Th) and idle time (see Ti). There is one exception, if “option logasap” was specified, then the time counting stops at the moment the log is emitted. In this case, a ‘+’ sign is prepended before the value, indicating that the final one will be larger. See section 8.4 “Timing Events” for more details.
“status_code” is the HTTP status code returned to the client. This status is generally set by the server, but it might also be set by HAProxy when the server cannot be reached or when its response is blocked by HAProxy.
“bytes_read” is the total number of bytes transmitted to the client when the log is emitted. This does include HTTP headers. If “option logasap” is specified, this value will be prefixed with a ‘+’ sign indicating that the final one may be larger. Please note that this value is a 64-bit counter, so log analysis tools must be able to handle it without overflowing.
“captured_request_cookie” is an optional “name=value” entry indicating that the client had this cookie in the request. The cookie name and its maximum length are defined by the “capture cookie” statement in the frontend configuration. The field is a single dash (’-’) when the option is not set. Only one cookie may be captured, it is generally used to track session ID exchanges between a client and a server to detect session crossing between clients due to application bugs. For more details, please consult the section “Capturing HTTP headers and cookies” below.
“captured_response_cookie” is an optional “name=value” entry indicating that the server has returned a cookie with its response. The cookie name and its maximum length are defined by the “capture cookie” statement in the frontend configuration. The field is a single dash (’-’) when the option is not set. Only one cookie may be captured, it is generally used to track session ID exchanges between a client and a server to detect session crossing between clients due to application bugs. For more details, please consult the section “Capturing HTTP headers and cookies” below.
“termination_state” is the condition the stream was in when the stream ended. This indicates the stream state, which side caused the end of stream to happen, for what reason (timeout, error, …), just like in TCP logs, and information about persistence operations on cookies in the last two characters. The normal flags should begin with “–”, indicating the stream was closed by either end with no data remaining in buffers. See below “Stream state at disconnection” for more details.
“actconn” is the total number of concurrent connections on the process when the stream was logged. It is useful to detect when some per-process system limits have been reached. For instance, if actconn is close to 512 or 1024 when multiple connection errors occur, chances are high that the system limits the process to use a maximum of 1024 file descriptors and that all of them are used. See section 3 “Global section” to find how to tune the system.
“feconn” is the total number of concurrent connections on the frontend when the stream was logged. It is useful to estimate the amount of resource required to sustain high loads, and to detect when the frontend’s “maxconn” has been reached. Most often when this value increases by huge jumps, it is because there is congestion on the backend servers, but sometimes it can be caused by a denial of service attack.
“beconn” is the total number of concurrent connections handled by the backend when the stream was logged. It includes the total number of concurrent connections active on servers as well as the number of connections pending in queues. It is useful to estimate the amount of additional servers needed to support high loads for a given application. Most often when this value increases by huge jumps, it is because there is congestion on the backend servers, but sometimes it can be caused by a denial of service attack.
“srv_conn” is the total number of concurrent connections still active on the server when the stream was logged. It can never exceed the server’s configured “maxconn” parameter. If this value is very often close or equal to the server’s “maxconn”, it means that traffic regulation is involved a lot, meaning that either the server’s maxconn value is too low, or that there aren’t enough servers to process the load with an optimal response time. When only one of the server’s “srv_conn” is high, it usually means that this server has some trouble causing the requests to take longer to be processed than on other servers.
“retries” is the number of connection retries experienced by this stream when trying to connect to the server. It must normally be zero, unless a server is being stopped at the same moment the connection was attempted. Frequent retries generally indicate either a network problem between HAProxy and the server, or a misconfigured system backlog on the server preventing new connections from being queued. This field may optionally be prefixed with a ‘+’ sign, indicating that the stream has experienced a redispatch after the maximal retry count has been reached on the initial server. In this case, the server name appearing in the log is the one the connection was redispatched to, and not the first one, though both may sometimes be the same in case of hashing for instance. So as a general rule of thumb, when a ‘+’ is present in front of the retry count, this count should not be attributed to the logged server.
“srv_queue” is the total number of requests which were processed before this one in the server queue. It is zero when the request has not gone through the server queue. It makes it possible to estimate the approximate server’s response time by dividing the time spent in queue by the number of requests in the queue. It is worth noting that if a stream experiences a redispatch and passes through two server queues, their positions will be cumulative. A request should not pass through both the server queue and the backend queue unless a redispatch occurs.
“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. It makes it possible to estimate the average queue length, which easily translates into a number of missing servers when divided by a server’s “maxconn” parameter. It is worth noting that if a stream experiences a redispatch, it may pass twice in the backend’s queue, and then both positions will be cumulative. A request should not pass through both the server queue and the backend queue unless a redispatch occurs.
“captured_request_headers” is a list of headers captured in the request due to the presence of the “capture request header” statement in the frontend. Multiple headers can be captured, they will be delimited by a vertical bar (’|’). When no capture is enabled, the braces do not appear, causing a shift of remaining fields. It is important to note that this field may contain spaces, and that using it requires a smarter log parser than when it’s not used. Please consult the section “Capturing HTTP headers and cookies” below for more details.
“captured_response_headers” is a list of headers captured in the response due to the presence of the “capture response header” statement in the frontend. Multiple headers can be captured, they will be delimited by a vertical bar (’|’). When no capture is enabled, the braces do not appear, causing a shift of remaining fields. It is important to note that this field may contain spaces, and that using it requires a smarter log parser than when it’s not used. Please consult the section “Capturing HTTP headers and cookies” below for more details.
“http_request” is the complete HTTP request line, including the method, request and HTTP version string. Non-printable characters are encoded (see below the section “Non-printable characters”). This is always the last field, and it is always delimited by quotes and is the only one which can contain quotes. If new fields are added to the log format, they will be added before this field. This field might be truncated if the request is huge and does not fit in the standard syslog buffer (1024 characters). This is the reason why this field must always remain the last one.
8.2.4. HTTPS log format
The HTTPS format is the best suited for HTTP over SSL connections. It is an extension of the HTTP format (see section 8.2.3 ) to which SSL related information are added. It is enabled when “option httpslog” is specified in the frontend. Just like the TCP and HTTP formats, the log is usually emitted at the end of the stream, unless “option logasap” is specified. A stream which matches the “monitor” rules will never logged. It is also possible not to log streams for which no data were sent by the client by specifying “option dontlognull” in the frontend. Successful connections will not be logged if “option dontlog-normal” is specified in the frontend.
The HTTPS log format is internally declared as a custom log format based on the exact following string, which may also be used as a basis to extend the format if required. Additionally the HAPROXY_HTTPS_LOG_FMT variable can be used instead. Refer to section 8.2.6 “Custom log format” to see how to use this:
This format is basically the HTTP one (see section 8.2.3 ) with new fields appended to it. The new fields (lines 17 and 18) will be detailed here. For the HTTP ones, refer to the HTTP section.
Example:
Field Format Extract from the example above 1 process_name ‘[’ pid ‘]:’ haproxy[14389]: 2 client_ip ‘:’ client_port 10.0.1.2:33317 3 ‘[’ request_date ‘]’ [06/Feb/2009:12:14:14.655] 4 frontend_name https-in 5 backend_name ‘/’ server_name static/srv1 6 TR ‘/’ Tw ‘/’ Tc ‘/’ Tr ‘/’ Ta* 10/0/30/69/109 7 status_code 200 8 bytes_read* 2750 9 captured_request_cookie - 10 captured_response_cookie - 11 termination_state —- 12 actconn ‘/’ feconn ‘/’ beconn ‘/’ srv_conn ‘/’ retries* 1/1/1/1/0 13 srv_queue ‘/’ backend_queue 0/0 14 ‘{’ captured_request_headers* ‘}’ {haproxy.1wt.eu} 15 ‘{’ captured_response_headers* ‘}’ {} 16 ‘"’ http_request ‘"’ “GET /index.html HTTP/1.1” 17 fc_err ‘/’ ssl_fc_err ‘/’ ssl_c_err ‘/’ ssl_c_ca_err ‘/’ ssl_fc_is_resumed 0/0/0/0/0 18 ssl_fc_sni ‘/’ ssl_version ‘/’ ssl_ciphers 1wt.eu/TLSv1.3/TLS_AES_256_GCM_SHA384
Detailed fields description:
“fc_err” is the status of the connection on the frontend’s side. It corresponds to the “fc_err” sample fetch. See the “fc_err” and “fc_err_str” sample fetch functions for more information.
“ssl_fc_err” is the last error of the first SSL error stack that was raised on the connection from the frontend’s perspective. It might be used to detect SSL handshake errors for instance. It will be 0 if everything went well. See the “ssl_fc_err” sample fetch’s description for more information.
“ssl_c_err” is the status of the client’s certificate verification process. The handshake might be successful while having a non-null verification error code if it is an ignored one. See the “ssl_c_err” sample fetch and the “crt-ignore-err” option.
“ssl_c_ca_err” is the status of the client’s certificate chain verification process. The handshake might be successful while having a non-null verification error code if it is an ignored one. See the “ssl_c_ca_err” sample fetch and the “ca-ignore-err” option.
“ssl_fc_is_resumed” is true if the incoming TLS session was resumed with the stateful cache or a stateless ticket. Don’t forgot that a TLS session can be shared by multiple requests.
“ssl_fc_sni” is the SNI (Server Name Indication) presented by the client to select the certificate to be used. It usually matches the host name for the first request of a connection. An absence of this field may indicate that the SNI was not sent by the client, and will lead haproxy to use the default certificate, or to reject the connection in case of strict-sni.
“ssl_version” is the SSL version of the frontend.
“ssl_ciphers” is the SSL cipher used for the connection.
8.2.5. Error log format
When an incoming connection fails due to an SSL handshake or an invalid PROXY protocol header, HAProxy will log the event using a shorter, fixed line format, unless a dedicated error log format is defined through an “error-log-format” line. By default, logs are emitted at the LOG_INFO level, unless the option “log-separate-errors” is set in the backend, in which case the LOG_ERR level will be used. Connections on which no data are exchanged (e.g. probes) are not logged if the “dontlognull” option is set.
The default format looks like this:
These fields just provide minimal information to help debugging connection failures.
By using the “error-log-format” directive, the legacy log format described above will not be used anymore, and all error log lines will follow the defined format.
An example of reasonably complete error-log-format follows, it will report the source address and port, the connection accept() date, the frontend name, the number of active connections on the process and on thit frontend, haproxy’s internal error identifier on the front connection, the hexadecimal OpenSSL error number (that can be copy-pasted to “openssl errstr” for full decoding), the client certificate extraction status (0 indicates no error), the client certificate validation status using the CA (0 indicates no error), a boolean indicating if the connection is new or was resumed, the optional server name indication (SNI) provided by the client, the SSL version name and the SSL ciphers used on the connection, if any. Note that backend connection errors are never reported here since in order for a backend connection to fail, it would have passed through a successful stream, hence will be available as regular traffic log (see option httplog or option httpslog).
8.2.6. Custom log format
Historically, custom log formats were only used to produce logs. But their convenience when used to
produce a string by assembling multiple complex expressions has got them adopted by many directives
which used to take only a string in argument and which may now also take an such a Custom log format
definition. Such arguments, which are commonly designated by “<fmt>” in this document, are defined
exactly the same way as the argument to the “log-format” directive, described here.
When it comes to logs and when the default log formats are not sufficient, it is possible to define new ones in very fine details. As creating a log-format from scratch is not always a trivial task, it is strongly recommended to first have a look at the existing formats (“option tcplog”, “option httplog”, “option httpslog”), pick the one looking the closest to the expectation, copy its “log-format” equivalent string and adjust it.
A Custom log format definition is a single argument from a configuration perspective. This means that it may not contain blanks (spaces or tabs), unless these blanks are escaped using the backslash character (’\’), or the whole definition is enclosed between quotes (which is the recommended way to use them). The use of unquoted format strings is not recommended anymore as history has shown that it was very error prone since a single missing backslash character could result in silent truncation of the format. Such configurations are still commonly encountered due to the massive adoption of log formats after version 1.5-dev9, 3 years before quotes were usable, but it is recommended to convert them to quoted strings and to drop the backslashes now.
A log format definition is made of any number of log format items separated by text and spaces. A log format item starts with character ‘%’. In order to emit a verbatim ‘%’, it must be preceded by another ‘%’ resulting in ‘%%’.
Logformat items may either be aliases or sample expressions:
If an item is named between square brackets (’[’ .. ‘]’) then it is used as a sample expression rule (see section 7.3 ). This it useful to add some less common information such as the client’s SSL certificate’s DN, or to log the key that would be used to store an entry into a stick table. It is also commonly used with non-log actions (header manipulation, variables etc).
Else if the item is named using an alpha-numerical name, it is an alias. (Refer to the table below for the list of available aliases)
Items can take arguments using braces (’{}’), and multiple arguments are separated by commas within the braces. Flags may be added or removed by prefixing them with a ‘+’ or ‘-’ sign (see below for the list of available flags).
Special alias “%o” may be used to propagate its flags to all other logformat items on the same format string. This is particularly handy with quoted (“Q”) and escaped (“E”) string formats.
Special alias “%OG” may be used to retrieve the log origin (when / where the log was generated) in a human readable format. It is particularly useful with “option logasap” because some log variables or sample fetches could report incomplete values or behave differently depending on when / where the logformat expression was evaluated. Possible values are:
- “sess_error”: log was generated during session error handling
- “sess_killed”: log was generated during session abortion (killed embryonic session)
- “txn_accept”: log was generated right after frontend conn was accepted
- “txn_request”: log was generated after client request was received
- “txn_connect”: log was generated after backend connection establishment
- “txn_response”: log was generated during server response handling
- “txn_close”: log was generated at the final txn step, before closing
- “unspec”: unknown or not specified “%OG” is only relevant in logging context.
Items can optionally be named using (’()’). The name must be provided right after ‘%’ (before arguments). It will automatically be used as key name when encoding flag such as “json” or “cbor” is set. When no encoding flag is specified (default), item name will be ignored. It is also possible to force the item’s output to a given type by appending ‘:type’ after the name, like this: %(itemname:itemtype)aliasname or %(itemname:itemtype)[expr] where itemtype may be ‘str’, ‘sint’ or ‘bool’. Specifying the type is only relevant when an encoding method is used. Also, it is supported to provide an empty name to force the output type on an anonymous item: %(:itemtype), ie: when encoding is not set globally, see flags definitions below for more information.
Due to the original goal of custom log formats to be used for logging only, there is a special case made of non-printable and unsafe characters (those outside ASCII codes 32 to 126 plus a few other ones) depending where they are used. Section 8.6 describes what’s done exactly for logs in order to make sure one will not send unsafe codes that alter the readability of the output in a terminal. When used to form header fields, health checks or payload responses, the rules are less strict and only characters forbidden in HTTP header fields are replaced by their hexadecimal encoding preceded by character ‘%’. This is normally not a problem, but it might affect the output when the character was expected to be reproduced verbatim (e.g. when building an error page or a full response payload, where line feeds could appear as “%0A”).
Note: in configuration directives “log-format”, “log-format-sd” and “unique-id-format”, spaces are considered as delimiters and are merged.
Note: when using the RFC5424 syslog message format, the characters ‘"’, ‘\’ and ‘]’ inside PARAM-VALUE should be escaped with ‘\’ as prefix (see https://tools.ietf.org/html/rfc5424#section-6.3.3 for more details). In such cases, the use of the flag “E” should be considered.
Supported item flags are (may be enabled/disabled from item’s arguments):
- Q: quote a string
- X: hexadecimal representation (IPs, Ports, %Ts, %rt, %pid)
- E: escape characters ‘"’, ‘\’ and ‘]’ in a string with ‘\’ as prefix (intended purpose is for the RFC5424 structured-data log formats)
- bin: try to preserve binary data, this can be useful with sample expressions that output binary data in order to preserve the original data. Be careful however, because it can obviously generate non-printable chars, including NULL-byte, which most syslog endpoints don’t expect. Thus it is mainly intended for use with set-var-fmt, rings and binary-capable log endpoints. This option can only be set globally (with %o), it will be ignored if set on an individual item’s options.
- json: automatically encode value in JSON format (when set globally, only named logformat items are considered) Incomplete numerical values (e.g.: ‘%B’ when logasap is used), which are normally prefixed with ‘+’ without encoding, will be encoded as-is. Also, ‘+E’ option will be ignored.
- cbor: automatically encode value in CBOR format (when set globally, only named logformat items are considered) By default, cbor encoded data is represented in HEX form so that it remains printable on stdout an can be used with usual syslog endpoints. As with json encoding, incomplete numerical values will be encoded as-is and ‘+E’ option will be ignored. When combined with ‘+bin’ option, it will directly generate raw binary CBOR payload. Be careful, because it will obviously generate non-printable chars, thus it is mainly intended for use with set-var-fmt, rings and binary-capable log endpoints.
Example:
Please refer to the table below for currently defined aliases:
R = Restrictions: H = mode http only; S = SSL only; L = log only
8.3. Advanced logging options
Some advanced logging options are often looked for but are not easy to find out just by looking at the various options. Here is an entry point for the few options which can enable better logging. Please refer to the keywords reference for more information about their usage.
8.3.1. Disabling logging of external tests
It is quite common to have some monitoring tools perform health checks on HAProxy. Sometimes it will be a layer 3 load-balancer such as LVS or any commercial load-balancer, and sometimes it will simply be a more complete monitoring system such as Nagios. When the tests are very frequent, users often ask how to disable logging for those checks. There are three possibilities:
if connections come from everywhere and are just TCP probes, it is often desired to simply disable logging of connections without data exchange, by setting “option dontlognull” in the frontend. It also disables logging of port scans, which may or may not be desired.
it is possible to use the “http-request set-log-level silent” action using a variety of conditions (source networks, paths, user-agents, etc).
if the tests are performed on a known URI, use “monitor-uri” to declare this URI as dedicated to monitoring. Any host sending this request will only get the result of a health-check, and the request will not be logged.
8.3.2. Logging before waiting for the stream to terminate
The problem with logging at end of connection is that you have no clue about what is happening during very long streams, such as remote terminal sessions or large file downloads. This problem can be worked around by specifying “option logasap” in the frontend. HAProxy will then log as soon as possible, just before data transfer begins. This means that in case of TCP, it will still log the connection status to the server, and in case of HTTP, it will log just after processing the server headers. In this case, the number of bytes reported is the number of header bytes sent to the client. In order to avoid confusion with normal logs, the total time field and the number of bytes are prefixed with a ‘+’ sign which means that real numbers are certainly larger.
8.3.3. Raising log level upon errors
Sometimes it is more convenient to separate normal traffic from errors logs, for instance in order to ease error monitoring from log files. When the option “log-separate-errors” is used, connections which experience errors, timeouts, retries, redispatches or HTTP status codes 5xx will see their syslog level raised from “info” to “err”. This will help a syslog daemon store the log in a separate file. It is very important to keep the errors in the normal traffic file too, so that log ordering is not altered. You should also be careful if you already have configured your syslog daemon to store all logs higher than “notice” in an “admin” file, because the “err” level is higher than “notice”.
8.3.4. Disabling logging of successful connections
Although this may sound strange at first, some large sites have to deal with multiple thousands of logs per second and are experiencing difficulties keeping them intact for a long time or detecting errors within them. If the option “dontlog-normal” is set on the frontend, all normal connections will not be logged. In this regard, a normal connection is defined as one without any error, timeout, retry nor redispatch. In HTTP, the status code is checked too, and a response with a status 5xx is not considered normal and will be logged too. Of course, doing is is really discouraged as it will remove most of the useful information from the logs. Do this only if you have no other alternative.
8.3.5. Log profiles
While some directives such as “log-format”, “log-format-sd”, “error-log-format” or “log-tag” make it possible to configure log formatting globally or at the proxy level, it may be relevant to configure such settings as close as possible to the log endpoints, that is, per “log” directive.
This is where “log-profile” section comes into play: “log-profile” may be defined anywhere in the
configuration. This section accepts a set of different keywords that are used to describe how the
logs emitted for a given log directive should be built.
From a “log” directive, one can choose to use a specific log-profile by its name. The same profile may be used from multiple “log” directives.
log-profile <name> Creates a new log profile identified as <name>
log-tag <string> Override syslog log tag set globally or per-proxy using “log-tag” directive.
on <step> [drop] [format <fmt>] [sd <sd_fmt>] Override the log-format string normally
used to build the log line at <step> logging step. <fmt> is used to override “log-format” or
“error-log-format” strings (depending on the <step>) whereas <sd_fmt> is used to override
“log-format-sd” string (both can be combined).
“drop” special keyword may be used to specify that no log should be emitted for the given <step>.
It takes precedence over “format” and “sd” if previously defined.
Possible values for <step> are:
- “accept” : override log-format if the log is generated right after frontend conn was accepted
- “request” : override log-format if the log is generated after client request was received
- “connect” : override log-format if the log is generated after backend connection establishment
- “response”: override log-format if the log is generated during server response handling
- “close” : override log-format if the log is generated at the final transaction (txn) step
- “error” : override error-log-format for if the log is generated due to a transaction error
- “any” : override both log-format and error-log-format for all logging steps, unless a more precise step override is declared.
See “do-log” action for relevant additional <step> values.
This setting is only relevant for “log” directives used from contexts where using “log-format” directive makes sense (e.g.: http and tcp proxies). Else it will simply be ignored.
Example:
8.4. Timing events
Timers provide a great help in troubleshooting network problems. All values are reported in milliseconds (ms). These timers should be used in conjunction with the stream termination flags. In TCP mode with “option tcplog” set on the frontend, 3 control points are reported under the form “Tw/Tc/Tt”, and in HTTP mode, 5 control points are reported under the form “TR/Tw/Tc/Tr/Ta”. In addition, three other measures are provided, “Th”, “Ti”, and “Tq”.
Timings events in HTTP mode:
Timings events in TCP mode:
Th: total time to accept tcp connection and execute handshakes for low level protocols. Currently, these protocols are proxy-protocol and SSL. This may only happen once during the whole connection’s lifetime. A large time here may indicate that the client only pre-established the connection without speaking, that it is experiencing network issues preventing it from completing a handshake in a reasonable time (e.g. MTU issues), or that an SSL handshake was very expensive to compute. Please note that this time is reported only before the first request, so it is safe to average it over all request to calculate the amortized value. The second and subsequent request will always report zero here.
This timer is named %Th as a log-format alias, and fc.timer.handshake as a sample fetch.
Ti: is the idle time before the HTTP request (HTTP mode only). This timer counts between the end of the handshakes and the first byte of the HTTP request. When dealing with a second request in keep-alive mode, it starts to count after the end of the transmission the previous response. When a multiplexed protocol such as HTTP/2 is used, it starts to count immediately after the previous request. Some browsers pre-establish connections to a server in order to reduce the latency of a future request, and keep them pending until they need it. This delay will be reported as the idle time. A value of -1 indicates that nothing was received on the connection.
This timer is named %Ti as a log-format alias, and req.timer.idle as a sample fetch.
TR: total time to get the client request (HTTP mode only). It’s the time elapsed between the first bytes received and the moment the proxy received the empty line marking the end of the HTTP headers. The value “-1” indicates that the end of headers has never been seen. This happens when the client closes prematurely or times out. This time is usually very short since most requests fit in a single packet. A large time may indicate a request typed by hand during a test.
This timer is named %TR as a log-format alias, and req.timer.hdr as a sample fetch.
Tq: total time to get the client request from the accept date or since the emission of the last byte of the previous response (HTTP mode only). It’s exactly equal to Th + Ti + TR unless any of them is -1, in which case it returns -1 as well. This timer used to be very useful before the arrival of HTTP keep-alive and browsers’ pre-connect feature. It’s recommended to drop it in favor of TR nowadays, as the idle time adds a lot of noise to the reports.
This timer is named %Tq as a log-format alias, and req.timer.tq as a sample fetch.
Tw: total time spent in the queues waiting for a connection slot. It accounts for backend queue as well as the server queues, and depends on the queue size, and the time needed for the server to complete previous requests. The value “-1” means that the request was killed before reaching the queue, which is generally what happens with invalid or denied requests.
This timer is named %Tw as a log-format alias, and req.timer.queue as a sample fetch.
Tc: total time to establish the TCP connection to the server. It’s the time elapsed between the moment the proxy sent the connection request, and the moment it was acknowledged by the server, or between the TCP SYN packet and the matching SYN/ACK packet in return. The value “-1” means that the connection never established.
This timer is named %Tc as a log-format alias, and bc.timer.connect as a sample fetch.
Tr: server response time (HTTP mode only). It’s the time elapsed between the moment the TCP connection was established to the server and the moment the server sent its complete response headers. It purely shows its request processing time, without the network overhead due to the data transmission. It is worth noting that when the client has data to send to the server, for instance during a POST request, the time already runs, and this can distort apparent response time. For this reason, it’s generally wise not to trust too much this field for POST requests initiated from clients behind an untrusted network. A value of “-1” here means that the last response header (empty line) was never seen, most likely because the server timeout stroke before the server managed to process the request or because the server returned an invalid response.
This timer is named %Tr as a log-format alias, and res.timer.hdr as a sample fetch.
Td: this is the total transfer time of the response payload till the last byte sent to the client. In HTTP it starts after the last response header (after Tr).
The data sent are not guaranteed to be received by the client, they can be stuck in either the kernel or the network.
This timer is named %Td as a log-format alias, and res.timer.data as a sample fetch.
Ta: total active time for the HTTP request, between the moment the proxy received the first byte of the request header and the emission of the last byte of the response body. The exception is when the “logasap” option is specified. In this case, it only equals (TR+Tw+Tc+Tr), and is prefixed with a ‘+’ sign. From this field, we can deduce “Td”, the data transmission time, by subtracting other timers when valid:
Timers with "-1" values have to be excluded from this equation. Note that
"Ta" can never be negative.
This timer is named %Ta as a log-format alias, and txn.timer.total as a
sample fetch.
- Tt: total stream duration time, between the moment the proxy accepted it and the moment both ends were closed. The exception is when the “logasap” option is specified. In this case, it only equals (Th+Ti+TR+Tw+Tc+Tr), and is prefixed with a ‘+’ sign. From this field, we can deduce “Td”, the data transmission time, by subtracting other timers when valid:
Timers with "-1" values have to be excluded from this equation. In TCP
mode, "Ti", "Tq" and "Tr" have to be excluded too. Note that "Tt" can never
be negative and that for HTTP, Tt is simply equal to (Th+Ti+Ta).
This timer is named %Tt as a log-format alias, and fc.timer.total as a
sample fetch.
Tu: total estimated time as seen from client, between the moment the proxy accepted it and the moment both ends were closed, without idle time. This is useful to roughly measure end-to-end time as a user would see it, without idle time pollution from keep-alive time between requests. This timer in only an estimation of time seen by user as it assumes network latency is the same in both directions. The exception is when the “logasap” option is specified. In this case, it only equals (Th+TR+Tw+Tc+Tr), and is prefixed with a ‘+’ sign.
This timer is named %Tu as a log-format alias, and txn.timer.user as a sample fetch.
These timers provide precious indications on trouble causes. Since the TCP protocol defines retransmit delays of 3, 6, 12… seconds, we know for sure that timers close to multiples of 3s are nearly always related to lost packets due to network problems (wires, negotiation, congestion). Moreover, if “Ta” or “Tt” is close to a timeout value specified in the configuration, it often means that a stream has been aborted on timeout.
Most common cases:
If “Th” or “Ti” are close to 3000, a packet has probably been lost between the client and the proxy. This is very rare on local networks but might happen when clients are on far remote networks and send large requests. It may happen that values larger than usual appear here without any network cause. Sometimes, during an attack or just after a resource starvation has ended, HAProxy may accept thousands of connections in a few milliseconds. The time spent accepting these connections will inevitably slightly delay processing of other connections, and it can happen that request times in the order of a few tens of milliseconds are measured after a few thousands of new connections have been accepted at once. Using one of the keep-alive modes may display larger idle times since “Ti” measures the time spent waiting for additional requests.
If “Tc” is close to 3000, a packet has probably been lost between the server and the proxy during the server connection phase. This value should always be very low, such as 1 ms on local networks and less than a few tens of ms on remote networks.
If “Tr” is nearly always lower than 3000 except some rare values which seem to be the average majored by 3000, there are probably some packets lost between the proxy and the server.
If “Ta” is large even for small byte counts, it generally is because neither the client nor the server decides to close the connection while HAProxy is running in tunnel mode and both have agreed on a keep-alive connection mode. In order to solve this issue, it will be needed to specify one of the HTTP options to manipulate keep-alive or close options on either the frontend or the backend. Having the smallest possible ‘Ta’ or ‘Tt’ is important when connection regulation is used with the “maxconn” option on the servers, since no new connection will be sent to the server until another one is released.
Other noticeable HTTP log cases (‘xx’ means any value to be ignored):
8.5. Stream state at disconnection
TCP and HTTP logs provide a stream termination indicator in the “termination_state” field, just before the number of active connections. It is 2-characters long in TCP mode, and is extended to 4 characters in HTTP mode, each of which has a special meaning:
- On the first character, a code reporting the first event which caused the stream to terminate:
- on the second character, the TCP or HTTP stream state when it was closed:
- the third character tells whether the persistence cookie was provided by the client (only in HTTP mode):
- the last character reports what operations were performed on the persistence cookie returned by the server (only in HTTP mode):
The combination of the two first flags gives a lot of information about what was happening when the stream or session terminated, and why it did terminate. It can be helpful to detect server saturation, network troubles, local system resource starvation, attacks, etc…
The most common termination flags combinations are indicated below. They are alphabetically sorted, with the lowercase set just after the upper case for easier finding and understanding.
Flags Reason
-- Normal termination.
CC The client aborted before the connection could be established to the
server. This can happen when HAProxy tries to connect to a recently
dead (or unchecked) server, and the client aborts while HAProxy is
waiting for the server to respond or for "timeout connect" to expire.
CD The client unexpectedly aborted during data transfer. This can be
caused by a browser crash, by an intermediate equipment between the
client and HAProxy which decided to actively break the connection,
by network routing issues between the client and HAProxy, or by a
keep-alive stream between the server and the client terminated first
by the client.
cD The client did not send nor acknowledge any data for as long as the
"timeout client" delay. This is often caused by network failures on
the client side, or the client simply leaving the net uncleanly.
CH The client aborted while waiting for the server to start responding.
It might be the server taking too long to respond or the client
clicking the 'Stop' button too fast.
cH The "timeout client" stroke while waiting for client data during a
POST request. This is sometimes caused by too large TCP MSS values
for PPPoE networks which cannot transport full-sized packets. It can
also happen when client timeout is smaller than server timeout and
the server takes too long to respond.
CQ The client aborted while its stream was queued, waiting for a server
with enough empty slots to accept it. It might be that either all the
servers were saturated or that the assigned server was taking too
long a time to respond.
CR The client aborted before sending a full HTTP request. Most likely
the request was typed by hand using a telnet client, and aborted
too early. The HTTP status code is likely a 400 here. Sometimes this
might also be caused by an IDS killing the connection between HAProxy
and the client. "option http-ignore-probes" can be used to ignore
connections without any data transfer.
cR The "timeout http-request" stroke before the client sent a full HTTP
request. This is sometimes caused by too large TCP MSS values on the
client side for PPPoE networks which cannot transport full-sized
packets, or by clients sending requests by hand and not typing fast
enough, or forgetting to enter the empty line at the end of the
request. The HTTP status code is likely a 408 here. Note: recently,
some browsers started to implement a "pre-connect" feature consisting
in speculatively connecting to some recently visited web sites just
in case the user would like to visit them. This results in many
connections being established to web sites, which end up in 408
Request Timeout if the timeout strikes first, or 400 Bad Request when
the browser decides to close them first. These ones pollute the log
and feed the error counters. Some versions of some browsers have even
been reported to display the error code. It is possible to work
around the undesirable effects of this behavior by adding "option
http-ignore-probes" in the frontend, resulting in connections with
zero data transfer to be totally ignored. This will definitely hide
the errors of people experiencing connectivity issues though.
CT The client aborted while its stream was tarpitted. It is important to
check if this happens on valid requests, in order to be sure that no
wrong tarpit rules have been written. If a lot of them happen, it
might make sense to lower the "timeout tarpit" value to something
closer to the average reported "Tw" timer, in order not to consume
resources for just a few attackers.
LC The request was intercepted and locally handled by HAProxy. The
request was not sent to the server. It only happens with a redirect
because of a "redir" parameter on the server line.
LR The request was intercepted and locally handled by HAProxy. The
request was not sent to the server. Generally it means a redirect was
returned, an HTTP return statement was processed or the request was
handled by an applet (stats, cache, Prometheus exported, lua applet...).
LH The response was intercepted and locally handled by HAProxy. Generally
it means a redirect was returned or an HTTP return statement was
processed.
SC The server or an equipment between it and HAProxy explicitly refused
the TCP connection (the proxy received a TCP RST or an ICMP message
in return). Under some circumstances, it can also be the network
stack telling the proxy that the server is unreachable (e.g. no route,
or no ARP response on local network). When this happens in HTTP mode,
the status code is likely a 502 or 503 here.
sC The "timeout connect" stroke before a connection to the server could
complete. When this happens in HTTP mode, the status code is likely a
503 or 504 here.
SD The connection to the server died with an error during the data
transfer. This usually means that HAProxy has received an RST from
the server or an ICMP message from an intermediate equipment while
exchanging data with the server. This can be caused by a server crash
or by a network issue on an intermediate equipment.
sD The server did not send nor acknowledge any data for as long as the
"timeout server" setting during the data phase. This is often caused
by too short timeouts on L4 equipment before the server (firewalls,
load-balancers, ...), as well as keep-alive sessions maintained
between the client and the server expiring first on HAProxy.
SH The server aborted before sending its full HTTP response headers, or
it crashed while processing the request. Since a server aborting at
this moment is very rare, it would be wise to inspect its logs to
control whether it crashed and why. The logged request may indicate a
small set of faulty requests, demonstrating bugs in the application.
Sometimes this might also be caused by an IDS killing the connection
between HAProxy and the server.
sH The "timeout server" stroke before the server could return its
response headers. This is the most common anomaly, indicating too
long transactions, probably caused by server or database saturation.
The immediate workaround consists in increasing the "timeout server"
setting, but it is important to keep in mind that the user experience
will suffer from these long response times. The only long term
solution is to fix the application.
sQ The stream spent too much time in queue and has been expired. See
the "timeout queue" and "timeout connect" settings to find out how to
fix this if it happens too often. If it often happens massively in
short periods, it may indicate general problems on the affected
servers due to I/O or database congestion, or saturation caused by
external attacks.
PC The proxy refused to establish a connection to the server because the
process's socket limit has been reached while attempting to connect.
The global "maxconn" parameter may be increased in the configuration
so that it does not happen anymore. This status is very rare and
might happen when the global "ulimit-n" parameter is forced by hand.
PD The proxy blocked an incorrectly formatted chunked encoded message in
a request or a response, after the server has emitted its headers. In
most cases, this will indicate an invalid message from the server to
the client. HAProxy supports chunk sizes of up to 2GB - 1 (2147483647
bytes). Any larger size will be considered as an error.
PH The proxy blocked the server's response, because it was invalid,
incomplete, dangerous (cache control), or matched a security filter.
In any case, an HTTP 502 error is sent to the client. One possible
cause for this error is an invalid syntax in an HTTP header name
containing unauthorized characters. It is also possible but quite
rare, that the proxy blocked a chunked-encoding request from the
client due to an invalid syntax, before the server responded. In this
case, an HTTP 400 error is sent to the client and reported in the
logs. Finally, it may be due to an HTTP header rewrite failure on the
response. In this case, an HTTP 500 error is sent (see
"tune.maxrewrite" and "http-response strict-mode" for more
inforomation).
PR The proxy blocked the client's HTTP request, either because of an
invalid HTTP syntax, in which case it returned an HTTP 400 error to
the client, or because a deny filter matched, in which case it
returned an HTTP 403 error. It may also be due to an HTTP header
rewrite failure on the request. In this case, an HTTP 500 error is
sent (see "tune.maxrewrite" and "http-request strict-mode" for more
inforomation).
PT The proxy blocked the client's request and has tarpitted its
connection before returning it a 500 server error. Nothing was sent
to the server. The connection was maintained open for as long as
reported by the "Tw" timer field.
RC A local resource has been exhausted (memory, sockets, source ports)
preventing the connection to the server from establishing. The error
logs will tell precisely what was missing. This is very rare and can
only be solved by proper system tuning.
The combination of the two last flags gives a lot of information about how persistence was handled by the client, the server and by HAProxy. This is very important to troubleshoot disconnections, when users complain they have to re-authenticate. The commonly encountered flags are:
8.6. Non-printable characters
In order not to cause trouble to log analysis tools or terminals during log consulting, non-printable characters are not sent as-is into log files, but are converted to the two-digits hexadecimal representation of their ASCII code, prefixed by the character ‘#’. The only characters that can be logged without being escaped are comprised between 32 and 126 (inclusive). Obviously, the escape character ‘#’ itself is also encoded to avoid any ambiguity ("#23"). It is the same for the character ‘"’ which becomes “#22”, as well as ‘{’, ‘|’ and ‘}’ when logging headers.
Note that the space character (’ ‘) is not encoded in headers, which can cause issues for tools relying on space count to locate fields. A typical header containing spaces is “User-Agent”.
Last, it has been observed that some syslog daemons such as syslog-ng escape the quote (’"’) with a backslash (’\’). The reverse operation can safely be performed since no quote may appear anywhere else in the logs.
8.7. Capturing HTTP cookies
Cookie capture simplifies the tracking a complete user session. This can be achieved using the “capture cookie” statement in the frontend. Please refer to section 4.2 for more details. Only one cookie can be captured, and the same cookie will simultaneously be checked in the request (“Cookie:” header) and in the response (“Set-Cookie:” header). The respective values will be reported in the HTTP logs at the “captured_request_cookie” and “captured_response_cookie” locations (see section 8.2.3 about HTTP log format). When either cookie is not seen, a dash (’-’) replaces the value. This way, it’s easy to detect when a user switches to a new session for example, because the server will reassign it a new cookie. It is also possible to detect if a server unexpectedly sets a wrong cookie to a client, leading to session crossing.
Examples:
It is possible to perform more advanced captures using “http-request” and “http-response” rules to assign cookies to variables of scope “txn”. The cookie values may then be extracted from the request or response using the “req.cook” and “res.cook” sample fetch functions (see section 7.3.6 ) and assigned to a variable using the “set-var” or “set-var-fmt” actions (see section 4.3 ). A custom log-format will then permit to present these variables where desired (see section 8.2.6 ).
8.8. Capturing HTTP headers (legacy)
Header captures are useful to track unique request identifiers set by an upper proxy, virtual host names, user-agents, POST content-length, referrers, etc. In the response, one can search for information about the response length, how the server asked the cache to behave, or an object location during a redirection.
There are two ways to perform header captures. The modern one involves setting variables from the headers to be captured, or from composite samples returned by “req.hdr_names”, “req.hdrs”, “res.hdr_names”, “res.hdrs” (see section 7.3.6 ) for all possibilities. These can be assigned to variables of scope “txn” using the “set-var” and “set-var-fmt” actions from the “http-request” and “http-response” rulesets (see section 4.3 ), which can then be referenced from custom log formats (see section 8.2.6 ). This is the recommended way to capture HTTP headers.
There is also the legacy method which predates the http-request rules and variables, which does not involve adjusting the log format, and which has also long been used both for logging and as an artificial way to convey request information all along the HTTP transaction, using the older “capture” rulesets. This is what is described in this section.
Legacy header captures are performed using the “capture request header” and “capture response header” statements in the frontend. Please consult their definition in section 4.2 for more details.
It is possible to include both request headers and response headers at the same time. Non-existent headers are logged as empty strings, and if one header appears more than once, only its last occurrence will be logged. Request headers are grouped within braces ‘{’ and ‘}’ in the same order as they were declared, and delimited with a vertical bar ‘|’ without any space. Response headers follow the same representation, but are displayed after a space following the request headers block. These blocks are displayed just before the HTTP request in the logs.
As a special case, it is possible to specify an HTTP header capture in a TCP frontend. The purpose is to enable logging of headers which will be parsed in an HTTP backend if the request is then switched to this HTTP backend.
Example:
8.9. Examples of logs
These are real-world examples of logs accompanied with an explanation. Some of them have been made up by hand. The syslog part has been removed for better reading. Their sole purpose is to explain how to decipher them.
>>> haproxy[674]: 127.0.0.1:33318 [15/Oct/2003:08:31:57.130] px-http \
px-http/srv1 6559/0/7/147/6723 200 243 - - ---- 5/3/3/1/0 0/0 \
"HEAD / HTTP/1.0"
=> long request (6.5s) entered by hand through 'telnet'. The server replied
in 147 ms, and the session ended normally ('----')
>>> haproxy[674]: 127.0.0.1:33319 [15/Oct/2003:08:31:57.149] px-http \
px-http/srv1 6559/1230/7/147/6870 200 243 - - ---- 324/239/239/99/0 \
0/9 "HEAD / HTTP/1.0"
=> Idem, but the request was queued in the global queue behind 9 other
requests, and waited there for 1230 ms.
=> request for a long data transfer. The "logasap" option was specified, so
the log was produced just before transferring data. The server replied in
14 ms, 243 bytes of headers were sent to the client, and total time from
accept to first data byte is 30 ms.
>>> haproxy[674]: 127.0.0.1:33320 [15/Oct/2003:08:32:17.925] px-http \
px-http/srv1 9/0/7/14/30 502 243 - - PH-- 3/2/2/0/0 0/0 \
"GET /cgi-bin/bug.cgi? HTTP/1.0"
=> the proxy blocked a server response either because of an "http-response
deny" rule, or because the response was improperly formatted and not
HTTP-compliant, or because it blocked sensitive information which risked
being cached. In this case, the response is replaced with a "502 bad
gateway". The flags ("PH--") tell us that it was HAProxy who decided to
return the 502 and not the server.
>>> haproxy[18113]: 127.0.0.1:34548 [15/Oct/2003:15:18:55.798] px-http \
px-http/`<NOSRV>` -1/-1/-1/-1/8490 -1 0 - - CR-- 2/2/2/0/0 0/0 ""
=> the client never completed its request and aborted itself ("C---") after
8.5s, while the proxy was waiting for the request headers ("-R--").
Nothing was sent to any server.
>>> haproxy[18113]: 127.0.0.1:34549 [15/Oct/2003:15:19:06.103] px-http \
px-http/`<NOSRV>` -1/-1/-1/-1/50001 408 0 - - cR-- 2/2/2/0/0 0/0 ""
=> The client never completed its request, which was aborted by the
time-out ("c---") after 50s, while the proxy was waiting for the request
headers ("-R--"). Nothing was sent to any server, but the proxy could
send a 408 return code to the client.
>>> haproxy[18989]: 127.0.0.1:34550 [15/Oct/2003:15:24:28.312] px-tcp \
px-tcp/srv1 0/0/5007 0 cD 0/0/0/0/0 0/0
=> This log was produced with "option tcplog". The client timed out after
5 seconds ("c----").
>>> haproxy[18989]: 10.0.0.1:34552 [15/Oct/2003:15:26:31.462] px-http \
px-http/srv1 3183/-1/-1/-1/11215 503 0 - - SC-- 205/202/202/115/3 \
0/0 "HEAD / HTTP/1.0"
=> The request took 3s to complete (probably a network problem), and the
connection to the server failed ('SC--') after 4 attempts of 2 seconds
(config says 'retries 3'), and no redispatch (otherwise we would have
seen "/+3"). Status code 503 was returned to the client. There were 115
connections on this server, 202 connections on this proxy, and 205 on
the global process. It is possible that the server refused the
connection because of too many already established.