HaProxy日志详解

文章首发站点:OpensGalaxy.com

本文参考自官方文档:http://cbonte.github.io/haproxy-dconv/1.5/configuration.html logging 部分,本文着重介绍haproxy日志格式、自定义日志格式和捕捉自定义http headers,更多详细内容请详读文档。

Log levels 日志级别

global 全局参数,如果实例上没设置参数,仅有log global那么每个实例都会使用该参数。
log global
log <address> [len <length>] <facility> [<level> [<minlevel>]]
address 日志发送的目的IP地址。
            - IPV4 默认UDP端口514  例如:127.0.0.1:514
            - IPV6 默认UDP端口514
            - 文件系统路径到scoket,保证文件是可写的。
length 日志输出行最大字符长度,值范围80-65535 默认值 1024
facility 必须是24个标准的syslog设施
             kern   user   mail   daemon auth   syslog lpr    news
             uucp   cron   auth2  ftp    ntp    audit  alert  cron2
             local0 local1 local2 local3 local4 local5 local6 local7
level 日志级别,可以设置一个最低日志级别,可以发送最低日志级别以上级别的日志信息
            emerg  alert  crit   err    warning notice info  debug
Example :

log global

log 127.0.0.1:514 local0 notice         

log 127.0.0.1:514 local0 notice notice

log ${LOCAL_SYSLOG}:514 local0 notice 

Log Formats

Haproxy 支持5种日志格式

1、默认格式:这是非常基本的,很少使用。它只提供关于传入连接的非常基本的信息 源IP:端口、目的IP:端口,和前端的名字。

Example :
    listen www
        mode http
        log global
        server srv1 127.0.0.1:8000

>>> Feb  6 12:12:09 localhost \
      haproxy[14385]: Connect from 10.0.1.2:33312 to 10.0.3.31:8012 \
      (www/HTTP)

    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)

2、TCP协议格式:通过“option tcplog” 启用该格式,这种格式提供了更丰富的信息,如定时器,连接数,队列大小等。这格式推荐纯TCP代理。

TCP协议格式字段定义串:
log-format %ci:%cp\ [%t]\ %ft\ %b/%s\ %Tw/%Tc/%Tt\ %B\ %ts\ %ac/%fc/%bc/%sc/%rc\ %sq/%bq


Example :
    frontend fnt
        mode tcp
        option tcplog
        log global
        default_backend bck

    backend bck
        server srv1 127.0.0.1:8000

>>> Feb  6 12:12:56 localhost \
      haproxy[14387]: 10.0.1.2:33313 [06/Feb/2009:12:12:51.443] fnt \
      bck/srv1 0/0/5007 212 -- 0/0/0/0/3 0/0
  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, 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.

  - "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 "Session 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 parameters" 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
    cumulated. 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 cumulated. A request should not pass
    through both the server queue and the backend queue unless a redispatch
    occurs.

3、HTTP协议格式:通过“option httplog” 启用该格式,http代理推荐使用该格式。

HTTP协议格式字段定义串:
    log-format %ci:%cp\ [%t]\ %ft\ %b/%s\ %Tq/%Tw/%Tc/%Tr/%Tt\ %ST\ %B\ %CC\ \
               %CS\ %tsc\ %ac/%fc/%bc/%sc/%rc\ %sq/%bq\ %hr\ %hs\ %{+Q}r

Example :
    frontend http-in
        mode http
        option httplog
        log global
        default_backend bck

    backend static
        server srv1 127.0.0.1:8000

>>> Feb  6 12:14:14 localhost \
      haproxy[14389]: 10.0.1.2:33317 [06/Feb/2009:12:14:14.655] http-in \
      static/srv1 10/0/30/69/109 200 2750 - - ---- 1/1/1/1/0 0/0 {1wt.eu} \
      {} "GET /index.html HTTP/1.1"
  Field   Format                                Extract from the example above
      1   process_name '[' pid ']:'                            haproxy[14389]:
      2   client_ip ':' client_port                             10.0.1.2:33317
      3   '[' accept_date ']'                       [06/Feb/2009:12:14:14.655]
      4   frontend_name                                                http-in
      5   backend_name '/' server_name                             static/srv1
      6   Tq '/' Tw '/' Tc '/' Tr '/' Tt*                       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, 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 TCP 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. This
    does not depend on the fact that the client has sent the request or not.

  - "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.

  - "Tq" is the total time in milliseconds spent waiting for the client to send
    a full HTTP request, not counting data. It can be "-1" if the connection
    was aborted before a complete request could be received. It should always
    be very small because a request generally fits in one single packet. Large
    times here generally indicate network trouble between the client and
    haproxy. See "Timers" below 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 "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
    request was aborted before a connection could be established. See "Timers"
    below 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 "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.

  - "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, 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.

  - "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 session was in when the session
    ended. This indicates the session state, which side caused the end of
    session 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
    session was closed by either end with no data remaining in buffers. See
    below "Session 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 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 parameters" 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 requests 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
    cumulated. 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 cumulated. 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.

4、CLF HTTP协议格式:相当于http协议格式。

CLF HTTP协议格式字段定义串:
    log-format %{+Q}o\ %{-Q}ci\ -\ -\ [%T]\ %r\ %ST\ %B\ \"\"\ \"\"\ %cp\ \
               %ms\ %ft\ %b\ %s\ \%Tq\ %Tw\ %Tc\ %Tr\ %Tt\ %tsc\ %ac\ %fc\ \
               %bc\ %sc\ %rc\ %sq\ %bq\ %CC\ %CS\ \%hrl\ %hsl

5、自定义格式

R var field name (8.2.2 and 8.2.3 for description) type
%o special variable, apply flags on all next var
%B bytes_read (from server to client) numeric
H %CC captured_request_cookie string
H %CS captured_response_cookie string
%H hostname string
H %HM HTTP method (ex: POST) string
H %HP HTTP request URI without query string (path) string
H %HQ HTTP request URI query string (ex: ?bar=baz) string
H %HU HTTP request URI (ex: /foo?bar=baz) string
H %HV HTTP version (ex: HTTP/1.0) string
%ID unique-id string
%ST status_code numeric
%T gmt_date_time date
%Tc Tc numeric
%Tl local_date_time date
H %Tq Tq numeric
H %Tr Tr numeric
%Ts timestamp numeric
%Tt Tt numeric
%Tw Tw numeric
%U bytes_uploaded (from client to server) numeric
%ac actconn numeric
%b backend_name string
%bc beconn (backend concurrent connections) numeric
%bi backend_source_ip (connecting address) IP
%bp backend_source_port (connecting address) numeric
%bq backend_queue numeric
%ci client_ip (accepted address) IP
%cp client_port (accepted address) numeric
%f frontend_name string
%fc feconn (frontend concurrent connections) numeric
%fi frontend_ip (accepting address) IP
%fp frontend_port (accepting address) numeric
%ft frontend_name_transport (‘~’ suffix for SSL) string
%lc frontend_log_counter numeric
%hr captured_request_headers default style string
%hrl captured_request_headers CLF style string list
%hs captured_response_headers default style string
%hsl captured_response_headers CLF style string list
%ms accept date milliseconds (left-padded with 0) numeric
%pid PID numeric
H %r http_request string
%rc retries numeric
%rt request_counter (HTTP req or TCP session) numeric
%s server_name string
%sc srv_conn (server concurrent connections) numeric
%si server_IP (target address) IP
%sp server_port (target address) numeric
%sq srv_queue numeric
S %sslc ssl_ciphers (ex: AES-SHA) string
S %sslv ssl_version (ex: TLSv1) string
%t date_time (with millisecond resolution) date
%ts termination_state string
H %tsc termination_state with cookie status string

R = Restrictions : H = mode http only ; S = SSL only

Example :

global
        maxconn 65535
        chroot /usr/local/haproxy
        uid 99
        gid 99
        daemon
        nbproc 1
        description haproxy
        pidfile /var/run/haproxy.pid
defaults
        log global
        mode http
        balance roundrobin
        option forceclose
        option dontlognull
        option redispatch
        option abortonclose
        log-format %ci:%cp\ [%t]\ %U\ %HM\ %HU\ %HV\ %ST\ %si:%sp

>>> Sep 12 10:17:52 localhost haproxy[22909]: 10.1.250.98:53300 [12/Sep/2016:10:17:52.532] 496 GET / HTTP/1.1 200 10.1.1.20:9090

错误日志

error日志格式:

 >>> Dec  3 18:27:14 localhost \
          haproxy[6103]: 127.0.0.1:56059 [03/Dec/2012:17:35:10.380] frt/f1: \
          Connection error during SSL handshake

  Field   Format                                Extract from the example above
      1   process_name '[' pid ']:'                             haproxy[6103]:
      2   client_ip ':' client_port                            127.0.0.1:56059
      3   '[' accept_date ']'                       [03/Dec/2012:17:35:10.380]
      4   frontend_name "/" bind_name ":"                              frt/f1:
      5   message                        Connection error during SSL handshake

捕捉 HTTP Headers

Example:
capture request header Host len 15
capture request header X-Forwarded-For len 15
capture request header Referer len 15

自定义headers
frontend webapp
        bind *:80
        capture request header test len 20
        capture request header test2 len 20

利用chrome的postman发送自定义headers

image

>>> Sep 12 15:25:19 localhost haproxy[23495]: 10.21.250.98:57362 [12/Sep/2016:15:25:19.145] 496 GET / HTTP/1.1 200 10.1.12.191:9090 {aaa|bbb}

发表评论