Forum Discussion

GavinW_29074's avatar
GavinW_29074
Icon for Nimbostratus rankNimbostratus
Dec 23, 2014

HTTP Payload logging breaks HTTP Keep-Alive

Afternoon all,

I've written an iRule to record the request/response payload on a REST HTTP API.

The rule looks like:
    when CLIENT_ACCEPTED {

            if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "Processing CLIENT_ACCEPTED." }

             Set the payload logging flag
            set log_payload 1
    }

    when HTTP_REQUEST priority 800 { 
            if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: Processing HTTP_REQUEST at priority 800..." }

             Skip logging if no members available
            if {$splunk_bypass}{
                    if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: Splunk HSL pool is down. Bypassing logging..." }
                    return
            }

             Don't allow data to be chunked
            if { [HTTP::version] eq "1.1" } {
                    if { [HTTP::header is_keepalive] } {
                            HTTP::header replace "Connection" "Keep-Alive"
                    }
                    if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: Switching to HTTP Version 1.0." }
                    HTTP::version "1.0"
            }

             Split out request headers and munge into string
            set headers [HTTP::header names]
            if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: Request HTTP Headers = $headers" }
            set request_headers "'"
            foreach header $headers {
                    set value [HTTP::header value $header]
                    if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: Request HTTP Header $header value = $value" }
                    append request_headers "$header=$value "
            }
            set request_headers [string trimright $request_headers " "]
            append request_headers "'"
    }

    when HTTP_REQUEST_DATA {
            if { $static::PayloadLoggerDebug or $f5_connection_debug }{ log local0.debug "$log_prefix: Collected [HTTP::payload length] bytes."}
            set request_payload [HTTP::payload]
    }

    when HTTP_RESPONSE priority 50 {
            if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: Processing HTTP_RESPONSE at priority 50..." }

             Skip logging if no members available
            if {$splunk_bypass}{
                    if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: Splunk HSL pool is down. Bypassing logging..." }
                    return
            }

             Split out the response headers and munge into string
            set headers [HTTP::header names]
            if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: Response HTTP Headers = $headers" }
            set response_headers "'"
            foreach header $headers {
                    set value [HTTP::header value $header]
                    if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: Response HTTP Header $header value = $value" }
                    append response_headers "$header=$value "
            }
            set response_headers [string trimright $response_headers " "]
            append response_headers "'"

             Collect the response
            if { $response_length > 0 } {
                    if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: Collecting $response_length bytes from response." }
                    HTTP::collect $response_length
            }

             Calculate actual content-length
            set response_length_real [HTTP::payload length]
            if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: Real response content-length = $response_length_real." }

             Correct the response_length to correct value if required. 
            if { $response_length != $response_length_real } {
                    if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: Updated \$response_length value." }
                    set response_length $response_length_real
                    if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: New \$response_length value is $response_length." }
            }
    }

    when HTTP_RESPONSE_DATA {
            if { $static::PayloadLoggerDebug or $f5_connection_debug } { log local0.debug "$log_prefix: Processing HTTP_RESPONSE_DATA." }

             Gather response data
            set response_payload "[HTTP::payload]"
    }

A lot of the above feeds into a larger iRule framework. E.g. we use a SplunkHTTPS iRule to actually do the HSL logging out to a syslog server. The 'HTTP::collect' is also called from that iRule aswell.

However when testing this iRule, I've identified an issue whereby it appears to be breaking HTTP Keep-alive connections to some of our GF3 application servers.

Removing this rule restores the keep-alive functionality.

Any pointers on how I can maintain the keep-alive functionality and also be able to log the request/response data?

Cheers Gavin

  •   if { [HTTP::header is_keepalive] } {
        HTTP::header replace "Connection" "Keep-Alive"
      }
    

    have you tried tcpdump? was connection keep-alive presented in all requests on serverside (between bigip and server)?

  • I was just trying that currently...

    It looks like the 'Connection: Keep-Alive' value is correctly passed, along with setting the HTTP proto to 1.0.

    However the response comes back with a 'Connection: close'.
    GET /cloudpost-web/rest/remote/3.0 HTTP/1.0
    Host: client.dev.post.card.co.uk
    Accept: */*
    Connection: Keep-Alive
    X-Forwarded-For: x.x.x.x
    
    HTTP/1.1 200 OK
    X-Powered-By: Servlet/3.0 JSP/2.2 (GlassFish Server Open Source Edition 3.1.2.2 Java/Oracle Corporation/1.7)
    Server: GlassFish Server Open Source Edition 3.1.2.2
    Content-Type: text/plain
    Date: Tue, 23 Dec 2014 15:31:21 GMT
    Connection: close
    
    POST Remote Resource 3.0
    

    However running direct to the application server with HTTP/1.1 works correctly and the connection is kept alive...

    Cheers

    Gav
  • It looks like the 'Connection: Keep-Alive' value is correctly passed, along with setting the HTTP proto to 1.0.

     

    However the response comes back with a 'Connection: close'.

     

    could it be server configuration?

     

  • Yeh, my money is on it being an application server issue... But testing directly with a HTTP/1.1 connection results in the correct keep-alive behaviour :(

     

    Will see if I can simulate the HTTP proto down-grade outside of the F5, and see how the app server behaves...

     

    Cheers

     

    Gav

     

  • OK, running a HTTP/1.0 direct against the Glassfish 3 application server yields the same came connection close behaviour...

     

    So it indeed looks to be an issue with the application server...

     

    Now to try and work out how to fix that... :(

     

    Cheers

     

    Gav

     

    • nitass's avatar
      nitass
      Icon for Employee rankEmployee
      do you really need to collect response payload? i think i do not see any action on the response payload.
    • GavinW_29074's avatar
      GavinW_29074
      Icon for Nimbostratus rankNimbostratus
      The response payload gets recorded in this iRule, then logged out to a syslog server in another iRule... It'd be nice to be able to log the payloads along with the access logs, but am discussing it's importance with the dev teams currently... It's a shame we can't capture the payload against a HTTP/1.1 connection... Cheers Gav