Forum Discussion

Amit585731's avatar
Amit585731
Icon for Nimbostratus rankNimbostratus
Jan 10, 2016

issue with irule

Dear Experts,

we are having an issue where application team requested us to log source IP address whenever user hits specific page. We created an irule to implement this but whenever I am hitting that page I am seeing multiple logs getting generated for one http request. Is there any thing I am doing wrong or its an issue with ltm.. earlier it also happened where application team complaint that for single connection there is multiple request coming form ltm due to which they are seeing their licensed getting over utilized.

Below is the irule and ltm log for one http request.

Please suggest:

irule

when HTTP_REQUEST { if {[HTTP::uri] starts_with "/xyz"} { log local0. "Client IP address: [IP::client_addr]" }

}

logs:

Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:37 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1 Jan 10 14:11:38 test_box info tmm[13056]: Rule /Common/test_iRule1 : Client IP address: 1.1.1.1

11 Replies

  • Vernon_97235's avatar
    Vernon_97235
    Historic F5 Account

    If HTTP Keep-Alive is in use in the client-side (and it probably is) then the client may make multiple requests over a single TCP connection. In that case, HTTP_REQUEST will fire for each client HTTP request. If you want it to happen only once per TCP connection:

    when CLIENT_ACCEPTED {
        set hit_test 0    
    }
    
    when HTTP_REQUEST {
        if { [HTTP::path starts_with "/xyz" and !$hit_test } {    
            log local0. "..."        
            set hit_test 1        
        }    
    }
    

    You should also consider remote logging using High Speed Logging, rather than local logging.

    • Amit585731's avatar
      Amit585731
      Icon for Nimbostratus rankNimbostratus
      Vernon, Thanks for your reply. But after adding this irule as well I am seeing that same IP address getting logged multiple times. Thanks
  • If HTTP Keep-Alive is in use in the client-side (and it probably is) then the client may make multiple requests over a single TCP connection. In that case, HTTP_REQUEST will fire for each client HTTP request. If you want it to happen only once per TCP connection:

    when CLIENT_ACCEPTED {
        set hit_test 0    
    }
    
    when HTTP_REQUEST {
        if { [HTTP::path starts_with "/xyz" and !$hit_test } {    
            log local0. "..."        
            set hit_test 1        
        }    
    }
    

    You should also consider remote logging using High Speed Logging, rather than local logging.

    • Amit585731's avatar
      Amit585731
      Icon for Nimbostratus rankNimbostratus
      Vernon, Thanks for your reply. But after adding this irule as well I am seeing that same IP address getting logged multiple times. Thanks
  • Actually, an even simpler mechanism (I feel silly for not having realized this before) is to do this:

    when CLIENT_ACCEPTED {
        log local0. "..."
    }
    

    This will fire only when the TCP connection is opened. If you are still seeing multiple logs for the same source IP, then one of two things is happening: 1. the client is opening multiple connections, possibly simultaneously; or 2. there is a bug. 1 is much more likely. If you want to validate:

    when CLIENT_ACCEPTED {
        log local0. "Received client request from ([IP::client_addr]:[TCP::client_port]) -> ([IP::local_addr]:[TCP::local_port])"
    }
    

    If the source port changes across requests, then the client is definitely opening multiple connections. If the source port is the same, then a

    tcpdump
    will tell you what's really happening:

    bash tcpdump -nni 0.0 tcp port 80 and host 
    

    where is the IP address of the Virtual Server to which the iRule is attached.

    • Amit585731's avatar
      Amit585731
      Icon for Nimbostratus rankNimbostratus
      Thanks Vernon for your help. I tried checking with tcpdump it seems for single request we are seeing multiple logging. I will try to open a case with f5 and see if this is bug... Thanks again for all your help.
    • Amit585731's avatar
      Amit585731
      Icon for Nimbostratus rankNimbostratus
      Thanks Vernon for your help. I tried checking with tcpdump it seems for single request we are seeing multiple logging. I will try to open a case with f5 and see if this is bug... Thanks again for all your help.
  • Vernon_97235's avatar
    Vernon_97235
    Historic F5 Account

    Actually, an even simpler mechanism (I feel silly for not having realized this before) is to do this:

    when CLIENT_ACCEPTED {
        log local0. "..."
    }
    

    This will fire only when the TCP connection is opened. If you are still seeing multiple logs for the same source IP, then one of two things is happening: 1. the client is opening multiple connections, possibly simultaneously; or 2. there is a bug. 1 is much more likely. If you want to validate:

    when CLIENT_ACCEPTED {
        log local0. "Received client request from ([IP::client_addr]:[TCP::client_port]) -> ([IP::local_addr]:[TCP::local_port])"
    }
    

    If the source port changes across requests, then the client is definitely opening multiple connections. If the source port is the same, then a

    tcpdump
    will tell you what's really happening:

    bash tcpdump -nni 0.0 tcp port 80 and host 
    

    where is the IP address of the Virtual Server to which the iRule is attached.

    • Amit585731's avatar
      Amit585731
      Icon for Nimbostratus rankNimbostratus
      Thanks Vernon for your help. I tried checking with tcpdump it seems for single request we are seeing multiple logging. I will try to open a case with f5 and see if this is bug... Thanks again for all your help.
    • Amit585731's avatar
      Amit585731
      Icon for Nimbostratus rankNimbostratus
      Thanks Vernon for your help. I tried checking with tcpdump it seems for single request we are seeing multiple logging. I will try to open a case with f5 and see if this is bug... Thanks again for all your help.
  • Hi Amit,

    to log a specific client IP just once for a given URI, you have to implement techniques that maintains a state across different TCP connections. This can be achived on the server-side using the

    [table]
    command or on the client-side using HTTP-cookies.

    Scenario 1: Using the session table

    when RULE_INIT {
        set static::log_interval 5 ; seconds
    }
    when HTTP_REQUEST {
        if { ( [string tolower [HTTP::uri]] starts_with "/xyz" ) and 
             ( [table lookup "[IP::client_addr]_logs" ] eq "" ) } then {
            log local0.debug "Client IP address: [IP::client_addr] has requested /xyz"
            table set "[IP::client_addr]_logs" "1" indef $static::log_interval
        }
    }
    

    Note: Keep in min that this technique would consume some memory for each stored

    [IP::client_addr]
    . So please dont use an almost indefinite log_interval. You have to free the memory after a certain time period... 😉

    Scenario 2: Using HTTP cookies

    when RULE_INIT {
        set static::log_interval 5 ; seconds
    }
    when HTTP_REQUEST {
        if { ( [string tolower [HTTP::uri]] starts_with "/xyz" ) and 
             ( [HTTP::cookie value "log_cookie"] ne [IP::client_addr] ) } then {
            log local0.debug "Client IP address: [IP::client_addr] has requested /xyz"
            set log_cookie 1
        }
    }
    when HTTP_RESPONSE {
        if { [info exist log_cookie] } then {
            unset -nocomplain log_cookie
            HTTP::header insert "Set-Cookie" "log_cookie=[IP::client_addr]; Max-Age=$static::log_interval"
        }
    }
    

    Note: Maintaining a cookie based session state wouldn't require memory ressources on your LTM, so you may use an almost indefinite log_interval. But keep in mind that this technique requires that the browsers do have to support cookies (which is normaly the case). In addition it would also log certain client IPs multiple times if more than one browser was used on a given client IP (e.g. Terminal Servers)

    Cheers, Kai