Tracing Requests Through HAProxy with AWS X-Ray

blog20190614-01.yaml

TotalBufferSizeMB: 0
Concurrency: 8
Region: "us-east-2"
Endpoint: ""
Socket:
  UDPAddress: "127.0.0.1:2000"
  TCPAddress: "127.0.0.1:2000"
Logging:
  LogRotation: true
  LogLevel: "prod"
  LogPath: ""
LocalMode: true
ResourceARN: ""
RoleARN: ""
NoVerifySSL: false
ProxyAddress: ""
Version: 2

blog20190614-02.ini

[default]
aws_access_key_id = ABCDE12345
aws_secret_access_key = DEFGHIJK1234567890

blog20190614-03.sh

$ sudo systemctl restart xray

blog20190614-04.log

[Info]  Initializing AWS X-Ray daemon 3.0.0
[Debug] Listening on UDP 127.0.0.1:2000
[Info]  Using buffer memory limit of 9 MB
[Info]  144 segment buffers allocated
[Debug] Using proxy address:
[Debug] Fetch region us-east-2 from commandline/config file
[Info]  Using region: us-east-2
[Debug] ARN of the AWS resource running the daemon:
[Debug] No Metadata set for telemetry records
[Debug] Using Endpoint: https://xray.us-east-2.amazonaws.com
[Debug] Telemetry initiated
[Debug] Using Endpoint: https://xray.us-east-2.amazonaws.com
[Debug] Batch size: 50
[Info]  Starting proxy http server on 127.0.0.1:2000

blog20190614-05.conf

module(load="imudp")
module(load="mmfields")
module(load="omfwd")

$UDPServerAddress *
$UDPServerRun 514

# Define the JSON template
template(name="jsondump" type="list") {
    constant(value="{\"format\": \"json\", \"version\": 1}\n")
    constant(value="{")
        property(outname="name" name="$!f4" format="jsonf") constant(value=",")
        property(outname="id" name="$!f28" format="jsonf") constant(value=",")
        constant(value="\"start_time\":") property(name="$.start_time_seconds_with_ms") constant(value=",")
        constant(value="\"end_time\":") property(name="$.end_time_seconds_with_ms") constant(value=",")
        property(outname="trace_id" name="$!f27" format="jsonf") constant(value=",")
        constant(value="\"annotations\": {")
            property(outname="termination_code" name="$!f16" format="jsonf")
        constant(value="}")
    constant(value="}")
}

if $programname == "haproxy" then {
    # Split log line by pipe character
    action(type="mmfields" separator="|")

    # Split up termination state code
    set $.first_event = substring($!f16, 0, 1);
    set $.session_state = substring($!f16, 1, 1);

    # Calculate timing values
    set $.start_time = $!f3 * 1000; # timestamp ms
    set $.start_time_ms = $.start_time + $.start_time_remainder_ms; # timestamp ms + subseconds
    set $.start_time_seconds = $.start_time_ms / 1000;
    set $.start_time_remainder_ms = $.start_time_ms % 1000;
    set $.start_time_seconds_with_ms = cstr($.start_time_seconds) & "." & cstr($.start_time_remainder_ms);

    set $.total_time = $!f11; # total time ms
    set $.end_time_ms = $.start_time_ms + cnum($.total_time);
    set $.end_time_seconds = cnum($.end_time_ms) / 1000;
    set $.end_time_remainder_ms = cnum($.end_time_ms) % 1000;
    set $.end_time_seconds_with_ms = cstr($.end_time_seconds) & "." & cstr($.end_time_remainder_ms);

    # Forward output to X-Ray daemon
    action(type="omfwd"
           Target="127.0.0.1"
           Port="2000"
           Protocol="udp"
           Template="jsondump")

    # Normal log to file
    /var/log/haproxy.log
    stop
}

blog20190614-06.json

{
  "metadata":{
     "session_state_at_disconnection":{
        "code":"--",
        "first_event":{
           "code":"-"
        },
        "session_state":{
           "code":"-"
        }
     },
     "connections":{
        "frontend":1,
        "backend":0,
        "active":1,
        "server":1,
        "retries":0
     },
     "queue":{
        "backend":"0",
        "server":"0"
     }
  },
  "http":{
     "request":{
        "client_ip":"192.168.50.1",
        "method":"GET",
        "user_agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:64.0) Gecko/20100101 Firefox/64.0",
        "url":"https://192.168.50.20/"
     },
     "response":{
        "content_length":180,
        "status":304
     }
  },
  "subsegments":[
     {
        "name":"client request time",
        "start_time":1548450631.575,
        "end_time":1548450631.575,
        "id":"e489b0cd0d0257db"
     },
     {
        "name":"queued time",
        "start_time":1548450631.575,
        "end_time":1548450631.575,
        "id":"c04e1af794b416c1"
     },
     {
        "name":"server connect time",
        "start_time":1548450631.575,
        "end_time":1548450631.575,
        "id":"5b87e848d757bffa"
     },
     {
        "name":"server response time",
        "start_time":1548450631.575,
        "end_time":1548450631.576,
        "id":"cdb0b85ec2bb843d"
     }
  ],
  "end_time":1548450631.576,
  "id":"7ccbed1a542b32aa",
  "trace_id":"1-5c4b7b47-2046a5bd0f3c747c6cedf6cb",
  "annotations":{
     "termination_code":"--"
  },
  "start_time":1548450631.575,
  "name":"fe_main~"
}

blog20190614-07.txt

X-Amzn-Trace-Id: Root=1-5c4b5f4c-751f363f251259f72bbbc792

blog20190614-08.cfg

global
    log 127.0.0.1:514 local0

defaults
    log global
    mode http
    option httplog
    timeout connect 20s
    timeout client 30s
    timeout server 30s
    timeout http-request 30s

frontend fe_main
    bind :80

    # Create custom headers as temporary holding places for info
    http-request set-header X-Scheme http
    http-request set-header X-Scheme https if { ssl_fc }
    http-request set-header X-TraceId %[rand,hex,bytes(8,8),lower]%[rand,hex,bytes(8,8),lower]%[rand,hex,bytes(8,8),lower]
    http-request set-header X-SegmentId1 %[rand,hex,bytes(8,8),lower]%[rand,hex,bytes(8,8),lower]
    http-request set-header X-SegmentId2 %[rand,hex,bytes(8,8),lower]%[rand,hex,bytes(8,8),lower]
    http-request set-header X-SegmentId3 %[rand,hex,bytes(8,8),lower]%[rand,hex,bytes(8,8),lower]
    http-request set-header X-SegmentId4 %[rand,hex,bytes(8,8),lower]%[rand,hex,bytes(8,8),lower]
    http-request set-header X-SegmentId5 %[rand,hex,bytes(8,8),lower]%[rand,hex,bytes(8,8),lower]

    # Declare capture slots for logging headers
    declare capture request len 512
    http-request capture req.fhdr(User-Agent) id 0

    declare capture request len 5
    http-request capture req.hdr(X-Scheme) id 1

    declare capture request len 512
    http-request capture req.hdr(Host) id 2

    declare capture request len 24
    http-request capture req.hdr(X-TraceId) id 3

    declare capture request len 16
    http-request capture req.hdr(X-SegmentId1) id 4

    declare capture request len 16
    http-request capture req.hdr(X-SegmentId2) id 5

    declare capture request len 16
    http-request capture req.hdr(X-SegmentId3) id 6

    declare capture request len 16
    http-request capture req.hdr(X-SegmentId4) id 7

    declare capture request len 16
    http-request capture req.hdr(X-SegmentId5) id 8

    declare capture response len 8
    http-response capture res.hdr(Content-Length) id 0

    # Generate a unique Trace ID
    unique-id-format %{+X}o\ 1-%[date,hex,bytes(8,8),lower]-%[capture.req.hdr(3)]
    http-request set-header X-Amzn-Trace-Id Root=%[unique-id,lower]

    # The fields to log:
    # ci = client IP
    # cp = client port
    # Ts = timestamp
    # ft = frontend name
    # b = backend name
    # s = server name
    # TR = time to receive 1st byte
    # Tw = time spent waiting in queue
    # Tc = time spent to establish server connection
    # Tr = server response time
    # Ta = total active time of request
    # ST = status code
    # B = bytes read
    # CC = captured request cookie
    # CS = captured response cookie
    # ts = termination state code
    # ac = active connections
    # fc = frontend connections
    # bc = backend connections
    # sc = server connections
    # rc = number of retries
    # sq = connections queued for server
    # bq = requests processed before this one
    # capture.req.method = HTTP method
    # capture.req.hdr(0) = User-Agent
    # scheme://URL
    # ID = trace ID
    # segment ID 1
    # segment ID 2
    # segment ID 3
    # segment ID 4
    # segment ID 5
    # capture.res.hdr(0) = Content-Length

    log-format "%ci|%cp|%Ts|%ft|%b|%s|%TR|%Tw|%Tc|%Tr|%Ta|%ST|%B|%CC|%CS|%ts|%ac|%fc|%bc|%sc|%rc|%sq|%bq|%[capture.req.method]|%[capture.req.hdr(0)]|%[capture.req.hdr(1)]://%[capture.req.hdr(2)]%HP|%ID|%[capture.req.hdr(4)]|%[capture.req.hdr(5)]|%[capture.req.hdr(6)]|%[capture.req.hdr(7)]|%[capture.req.hdr(8)]|%[capture.res.hdr(0)]"

    default_backend be_servers

backend be_servers
    server s1 server:80 check

blog20190614-09.cfg

http-request set-header X-Scheme http if !{ ssl_fc }
http-request set-header X-Scheme https if { ssl_fc }
http-request set-header X-TraceId %[rand,hex,bytes(8,8),lower]%[rand,hex,bytes(8,8),lower]%[rand,hex,bytes(8,8),lower]
http-request set-header X-SegmentId %[rand,hex,bytes(8,8),lower]%[rand,hex,bytes(8,8),lower]

blog20190614-10.cfg

declare capture request len 512
http-request capture req.fhdr(User-Agent) id 0

declare capture request len 5
http-request capture req.hdr(X-Scheme) id 1
  
declare capture request len 512
http-request capture req.hdr(Host) id 2
  
declare capture request len 24
http-request capture req.hdr(X-TraceId) id 3

declare capture request len 16
http-request capture req.hdr(X-SegmentId1) id 4

blog20190614-11.cfg

unique-id-format %{+X}o\ 1-%[date,hex,bytes(8,8),lower]-%[capture.req.hdr(3)]
http-request set-header X-Amzn-Trace-Id Root=%[unique-id,lower]

blog20190614-12.cfg

log-format "%ci|%cp|%Ts|%ft|%b|%s|%TR|%Tw|%Tc|%Tr|%Ta|%ST|%B|%CC|%CS|%ts|%ac|%fc|%bc|%sc|%rc|%sq|%bq|%[capture.req.method]|%[capture.req.hdr(0)]|%[capture.req.hdr(1)]://%[capture.req.hdr(2)]%HP|%ID|%[capture.req.hdr(4)]|%[capture.req.hdr(5)]|%[capture.req.hdr(6)]|%[capture.req.hdr(7)]|%[capture.req.hdr(8)]|%[capture.res.hdr(0)]"

blog20190614-13.txt

192.168.64.1|46876|1557951572|fe_main|be_servers|s1|0|0|0|1|1|200|822|-|-|--|1|1|0|1|0|0|0|GET|Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Ubuntu Chromium/73.0.3683.86 Chrome/73.0.3683.86 Safari/537.36|http://localhost:8080/|1-5cdc7454-67119dff53f9270c0044df8b|667170f54e7ef382|7f59ddcf6e001372|558034ce7f64d663|7788ecb50abfb8e0|148d9bbe6cb5ea07|719

blog20190614-14.cfg

http-request del-header X-Scheme
http-request del-header X-TraceId
http-request del-header X-SegmentId1