Forum Discussion

TJ_Vreugdenhil's avatar
Mar 03, 2014

APM W3C Local Logging iRule

Hi

 

We are using the local logging irule found here on devcentral: https://devcentral.f5.com/wiki/irules.FormattedLoggingForW3c.ashx

 

Everything seems to populate correctly, except for the HTTP::username field as seen in the log message below: https://devcentral.f5.com/wiki/iRules.HTTP__username.ashx

 

info: Rule/Common/LOCAL_LOGGING : virtual=/Common/F5RDP client_ip=10.26.243.122 client_port=44012 lb_server=127.1.1.3:8080 host=172.26.4.59 username= request="GET/vesk/webtop=Common/RDP&webtop_type=webtop_full HTTP/1.1" server_status=200 content_length=0 resp_time=8 user_agent="Mozilla/5.0 (Windows NT 6.1; rv:26.0) Gecko/20100101 Firefox/26.0]" referer=https://172.26.1.1/my.policy

 

Any thoughts?

 

Thanks!

 

9 Replies

  • The HTTP::username command is used to retrieve the username from an HTTP Basic authentication request (Header: Authorization: Basic [bsae64-encoded user:pass]. So you would necessarily need to prompt the user for Basic authentication in order to get this value:

    if { not ( [HTTP::header exists Authorization] ) } {
        set body "Authentication FailuredError: Authentication Failure"
        HTTP::respond 401 content  $body WWW-Authenticate "Basic realm=\"[HTTP::header Host]\"" Connection Close
    }
    
  • Hi Kevin - Since we are applying this to an APM VIP, couldn't I just use this under the "when HTTP_REQUEST" or would I have to do something different such as your post here:

    [link text](https://devcentral.f5.com/questions/apm-ssl-user-login-logout-logging)
    
    when HTTP_REQUEST {
       set username [ACCESS::session data get session.logon.last.username]
    }
    when HTTP_RESPONSE {
       set log_msg ""
       append log_msg "username=$username "
       log local0. $log_msg
    }
    
  • The real issue is going to be when you collect the username. The original article assumes you're getting it from an initial HTTP Basic authentication prompt. But since in this case you're probably getting it from an APM logon page, the following code may be more appropriate:

     

    when ACCESS_ACL_ALLOWED {
        set http_request "\"[HTTP::method] [HTTP::uri] HTTP/[HTTP::version]\""
        set http_request_time [clock clicks -milliseconds]
        set http_user_agent "\"[HTTP::header User-Agent]]\""
        set http_host [HTTP::host]
        set http_username [ACCESS::session data get session.logon.last.username]
        set client_ip [IP::remote_addr]
        set client_port [TCP::remote_port]
        set http_request_uri [HTTP::uri]
        set referer [HTTP::header value referer]
    }
    when HTTP_RESPONSE {
        set response_time [expr [clock clicks -milliseconds] - $http_request_time]
        set virtual [virtual]
        set content_length 0
        if { [HTTP::header exists "Content-Length"] } {
            set content_length [HTTP::header "Content-Length"]
        }
        set lb_server "[LB::server addr]:[LB::server port]"
        if { [string compare "$lb_server" ""] == 0 } {
            set lb_server ""
        }
        set status_code [HTTP::status]
        set content_type [HTTP::header "Content-type"]
        set log_msg ""
        append log_msg "virtual=$virtual "
        append log_msg "client_ip=$client_ip "
        append log_msg "client_port=$client_port "
        append log_msg "lb_server=$lb_server "
        append log_msg "host=$http_host "
        append log_msg "username=$http_username "
        append log_msg "$http_request_uri "
        append log_msg "request=$http_request "
        append log_msg "server_status=$status_code "
        append log_msg "content_type=$content_type "
        append log_msg "content_length=$content_length "
        append log_msg "resp_time=$response_time "
        append log_msg "user_agent=$http_user_agent "
        append log_msg "referer=$referer"
           log  local0. $log_msg
        log local0. $log_msg
    }

    Notice this version is basically swapping the HTTP_REQUEST event for the ACCESS_ACL_ALLOWED event, and collecting the username in the session.logon.last.username APM session variable.

     

  • Hi Kevin - In using the iRule above and I get a TCL error that it doesn't recognize the http_request_time in the HTTP_RESPONSE.

    So what I did was move everything out of the ACCESS_ACL_ALLOWED event except for the username variable and I again get a TCL error in the HTTP_RESPONSE but now just for the http_username.

    It looks like the ACCESS events and the HTTP events do not play nice together.

    Would something like this work:

    when HTTP_REQUEST {
       set http_request "\"[HTTP::method] [HTTP::uri] HTTP/[HTTP::version]\""
       set http_request_time [clock clicks -milliseconds]
       set http_host [HTTP::host]
       set client_ip [IP::remote_addr]
       set client_port [TCP::remote_port]
       set http_request_uri [HTTP::uri]
       set referer [HTTP::header value referer]
    }
    
    when ACCESS_SESSION_STARTED {
     set userid [ACCESS::session data get "session.logon.last.username"]
     set userip [ACCESS::session data get "session.user.clientip"] 
     set useragent [ACCESS::session data get "session.user.agent"]" 
    }
    
    when ACCESS_POLICY_COMPLETED { 
        set log_msg ""
        append log_msg "userid=$userid "
        append log_msg "userip=$userip "
        append log_msg "useragent=$useragent "
        log local0. $log_msg
    }
    
    when HTTP_RESPONSE {
        set response_time [expr [clock clicks -milliseconds] - $http_request_time]
        set virtual [virtual]
        set content_length 0
        if { [HTTP::header exists "Content-Length"] } {
            set content_length [HTTP::header "Content-Length"]
        }
        set lb_server "[LB::server addr]:[LB::server port]"
        if { [string compare "$lb_server" ""] == 0 } {
            set lb_server ""
        }
        set status_code [HTTP::status]
        set content_type [HTTP::header "Content-type"]
        append log_msg "virtual=$virtual "
        append log_msg "client_ip=$client_ip "
        append log_msg "client_port=$client_port "
        append log_msg "lb_server=$lb_server "
        append log_msg "host=$http_host "
        append log_msg "$http_request_uri "
        append log_msg "request=$http_request "
        append log_msg "server_status=$status_code "
        append log_msg "content_length=$content_length "
        append log_msg "content_type=$content_type "
        append log_msg "resp_time=$response_time "
        append log_msg "referer=$referer"
           log  local0. $log_msg
        log local0. $log_msg
    }
    

    or how about putting the username in a HTTP header like this:

    when ACCESS_ACL_ALLOWED {
       set user [ACCESS::session data get "session.logon.last.username"]
       HTTP::header insert "X-USERNAME" $user
    }
    
    when HTTP_RESPONSE {
        set log_msg ""
        append log_msg "user=$user "
        log local0. $log_msg
    }
    

    I would also like to know where I can find a list of ACCESS:session data get variables? Also would it be easier to log this data by using ASM?

    Thanks!

  • It looks like the ACCESS events and the HTTP events do not play nice together.

     

    What version are you running, and what is your access policy doing? I've tested this on an 11.4 and 11.5 system without any errors.

     

    I would also like to know where I can find a list of ACCESS:session data get variables?

     

    There really is no definitive list, given that each process (ex. LDAP query, Kerberos SSO, etc.) will insert its own session variables. Your best bet is to either run an APM report in the GUI or dump the "created" session variables using the sessiondump -allkeys command in the shell. Here is a small list of common session variables though:

     

    http://support.f5.com/kb/en-us/products/big-ip_apm/manuals/product/apm-config-11-4-0/apm_config_sessionvars.html?sr=35265198

     

    Also would it be easier to log this data by using ASM?

     

    You could, but you could also do the same thing using the LTM request logging profile:

     

    http://support.f5.com/kb/en-us/products/big-ip-aam/manuals/product/aam-implementations-11-4-0/20.html?sr=33764514

     

  • We are running 11.4.1 HF3.

    The iRule takes but when you begin to try to send traffic to the APM VIP it either fails completely in the browser with a reset or doesn't log correctly because it identifies TCL errors. Below is our basic access-policy and TCL errors below. If you got it to work on a APM VIP, do you mind sharing your policy, VIP and iRule config?

    apm policy access-policy /Common/F5RDP {
        caption general
        default-ending /Common/F5RDP_end_deny
        items {
            /Common/F5RDP_act_active_directory_auth { }
            /Common/F5RDP_act_logon_page {
                priority 2
            }
            /Common/F5RDP_act_radius_auth { }
            /Common/F5RDP_act_resource_assign {
                priority 3
            }
            /Common/F5RDP_act_variable_assign { }
            /Common/F5RDP_end_allow {
                priority 5
            }
            /Common/F5RDP_end_deny {
                priority 4
            }
            /Common/F5RDP_ent_in { }
        }
        start-item /Common/F5RDP_ent_in
    }
    
    
    
    After connecting to page
    Mar  5 13:32:28 LTM1 info tmm1[12688]: Rule /Common/APM_LOCAL_LOGGING_TEST1 : virtual=/Common/F5RDP client_ip=10.26.243.128 client_port=51038 lb_server=127.0.0.1:10001 host=172.30.1.1 request="GET /my.policy HTTP/1.1" server_status=302 content_length=169 resp_time=3 referer=
    Mar  5 13:32:28 LTM1 info tmm1[12688]: Rule /Common/APM_LOCAL_LOGGING_TEST1 : virtual=/Common/F5RDP client_ip=10.26.243.128 client_port=51038 lb_server=127.0.0.1:10001 host=172.30.1.1 request="GET /my.policy HTTP/1.1" server_status=302 content_length=169 resp_time=3 referer=virtual=/Common/F5RDP client_ip=10.26.243.128 client_port=51038 lb_server=127.1.1.3:8080 host= request="GET /renderer/agent_logon_page_form.eui?f2_name=password2&f2_varname=password2&f3_type=text&f3_name=hostname&f3_varname=hostname&f4_type=password&f4_name=password&f4_varname=password HTTP/1.0" server_status=200 content_length=13703 resp_time=1 referer=
    
    
    After putting in variables on page
    Mar  5 13:32:54 LTM1 info tmm[12688]: Rule /Common/APM_LOCAL_LOGGING_TEST1 : virtual=/Common/F5RDP client_ip=10.26.243.128 client_port=52373 lb_server=127.0.0.1:10001 host=172.30.1.1 request="POST /my.policy HTTP/1.1" server_status=200 content_length=43 resp_time=947 referer=https://172.30.1.1/my.policy
    Mar  5 13:32:54 LTM1 err tmm[12688]: 01220001:3: TCL error: /Common/APM_LOCAL_LOGGING_TEST1  - can't read "userid": no such variable     while executing "append log_msg "userid=$userid ""
    Mar  5 13:32:54 LTM1 info tmm1[12688]: Rule /Common/APM_LOCAL_LOGGING_TEST1 : virtual=/Common/F5RDP client_ip=10.26.243.128 client_port=52472 lb_server=127.0.0.1:10001 host=172.30.1.1 request="GET /my.policy HTTP/1.1" server_status=302 content_length=169 resp_time=3 referer=https://172.30.1.1/my.policy
    Mar  5 13:32:54 LTM1 info tmm1[12688]: Rule /Common/APM_LOCAL_LOGGING_TEST1 : virtual=/Common/F5RDP client_ip=10.26.243.128 client_port=52472 lb_server=127.0.0.1:10001 host=172.30.1.1 request="GET /my.policy HTTP/1.1" server_status=302 content_length=169 resp_time=3 referer=https://172.30.1.1/my.policyvirtual=/Common/F5RDP client_ip=10.26.243.128 client_port=52472 lb_server=127.1.1.3:8080 host= request="GET /renderer/agent_logon_page_form.eui?f2_name=password2&f2_varname=password2&f3_type=text&f3_name=hostname&f3_varname=hostname&f4_type=password&f4_name=password&f4_varname=password HTTP/1.0" server_status=200 content_length=13703 resp_time=1 referer=
    
    After attempting to log in 3 times I get “connection reset and the following log
    Mar  5 13:33:25 LTM1 info tmm[12688]: Rule /Common/APM_LOCAL_LOGGING_TEST1 : virtual=/Common/F5RDP client_ip=10.26.243.128 client_port=54495 lb_server=127.0.0.1:10001 host=172.30.1.1 request="POST /my.policy HTTP/1.1" server_status=200 content_length=43 resp_time=444 referer=https://172.30.1.1/my.policy
    Mar  5 13:33:25 LTM1 err tmm[12688]: 01220001:3: TCL error: /Common/APM_LOCAL_LOGGING_TEST1  - can't read "userid": no such variable     while executing "append log_msg "userid=$userid ""
    
    Results from test1
    After connecting to page I get “connection reset and the following log
    Mar  5 13:36:03 LTM1 err tmm[12688]: 01220001:3: TCL error: /Common/APM_LOCAL_LOGGING_TEST2  - can't read "user": no such variable     while executing "append log_msg "user=$user ""
    
  • I think I see what's going on. Somewhere you have the following in your iRule:

    ACCESS::restrict_irule_events disable 
    

    I'm using the exact iRule from above, but without this command and it doesn't fail, though it doesn't log anything either. To make this work, change the ACCESS_ACL_ALLOWED back to HTTP_REQUEST and test again.

  • Here is what I ended with. The sessiondump was a big help. Thank you sir!

    ltm rule APM_LOCAL_LOGGING {
        version 1.0 - edits by TJ Vreugdenhil - added APM variables
    This iRule should be applied to VIP's associated with APM's. If you would like to find more APM
    variables to log, use the 'sessiondump ' after a user is logged in to see the list 
    possible variables to log agaisnt. 
    when HTTP_REQUEST {
       
        Save Request Side Information
       
       set http_request "\"[HTTP::method] [HTTP::uri] HTTP/[HTTP::version]\""
       set http_request_time [clock clicks -milliseconds]
       set http_user_agent "\"[HTTP::header User-Agent]]\""
       set http_host [HTTP::host]
       set client_ip [IP::remote_addr]
       set client_port [TCP::remote_port]
       set http_request_uri [HTTP::uri]
       set referer [HTTP::header value referer]
    }
    
    when HTTP_RESPONSE {
       set apmprofile [ACCESS::session data get "session.access.profile"] 
       set sessionid [ACCESS::session data get "session.user.sessionid"] 
       set userid [ACCESS::session data get "session.logon.last.logonname"] 
       set userip [ACCESS::session data get "session.user.clientip"]   
       set response_time [expr [clock clicks -milliseconds] - $http_request_time]
       set virtual [virtual]
       set content_length 0
       if { [HTTP::header exists "Content-Length"] } {
          set content_length [HTTP::header "Content-Length"]
       }
       set lb_server "[LB::server addr]:[LB::server port]"
       if { [string compare "$lb_server" ""] == 0 } {
          set lb_server ""
       }
       set status_code [HTTP::status]
       set content_type [HTTP::header "Content-type"]
       set log_msg ""
       append log_msg "sessionid=$sessionid "
       append log_msg "apmprofile=$apmprofile "   
       append log_msg "virtual=$virtual "
       append log_msg "userid=$userid " 
       append log_msg "userip=$userip "   
       append log_msg "client_ip=$client_ip "
       append log_msg "client_port=$client_port "
       append log_msg "lb_server=$lb_server "
       append log_msg "host=$http_host "
       append log_msg "$http_request_uri "
       append log_msg "request=$http_request "
       append log_msg "server_status=$status_code "
       append log_msg "content_type=$content_type "
       append log_msg "content_length=$content_length "
       append log_msg "resp_time=$response_time "
       append log_msg "user_agent=$http_user_agent "
       append log_msg "referer=$referer"
       log  local0. $log_msg
       log local0. $log_msg
    }
    }
    

    Here is the log message:

    `Mar  6 10:33:01 OR0506DA05 info tmm[12688]: Rule /Common/APM_LOCAL_LOGGING : sessionid=9ce2d922 apmprofile=/Common/RDP-NO-AUTH-TEST virtual=/Common/F5VIPSPORTAL userid=TJ userip=10.26.243.127 client_ip=10.26.243.127 client_port=18935 lb_server=127.1.1.2:8080 host=172.26.4.57 request="GET /vdesk/resource_info.xml HTTP/1.1" server_status=200 content_length=1666 resp_time=2 user_agent="Mozilla/5.0 (Windows NT 6.1; rv:27.0) Gecko/20100101 Firefox/27.0]" referer=https://172.26.1.1/vdesk/webtop.eui?webtop=/Common/RDP&webtop_type=webtop_full`
    
  • Just out of curiosity, do you have

    ACCESS::restrict_irule_events disable 
    

    applied in this iRule or another attached to the VIP?