Forum Discussion

J_Aldrich's avatar
J_Aldrich
Icon for Altostratus rankAltostratus
Aug 03, 2021

iRule Help. How do I add a 20 second time delay before log message runs?

Hello,

 

I am trying to create a log message whether or not a user was allowed or denied by the access policy. When I run the code, it always returns a log message with "not started" rather than "allowed" or "deny"... My thoughts were to add a 20 second delay before the log message runs in order to compensate for this. When I add the "after 20000" or "after 20000 -periodic {" Nothing seems to populate in the log. Am I doing something wrong? Here is an example of my code:

 

when HTTP_REQUEST {

set status 0

if {[HTTP::uri] contains "/login"} {

set status 1

}

}

 

when ACCESS_SESSION_STARTED {

if {$status equals 1 } {

set RESULT [ACCESS::session data get session.policy.result]

ACCESS::session data set session.custom.result $RESULT

 

after 20000 -periodic {

log local0. "User was $RESULT by the access policy"

}

}

}

 

 

 

  • It is always better to avoid artificial connection processing delays via the iRule after command, unless absolutely necessary. It simply delays results for the client. The idea is for a connection to get set up and complete quickly - in sub-second time (not 20 seconds). In your case, the ACCESS_SESSION_STARTED event occurs at the start of access policy processing, before the policy has produced a result. My guess is you were trying to get around that issue by delaying subsequent iRule command execution. More importantly, F5 recommends using built-in functions rather than an iRule when those built-in function exists. APM already logs access results for each access attempt in its logs. (By default, it writes to /var/log/apm.) You can customize the information that is logged (and where it is logged) but, even in its default configuration, I believe APM produces a more informatory message than what you are trying to write in your example.

    Is there a specific reason why you want to write additional log messages that convey a subset of that same information from within an iRule?

    If you still want to proceed with the iRule, I believe the issue you are experiencing is related to the timing of the event you have selected, as I mentioned earlier. You might try later events, such as ACCESS_ACL_ALLOWED and ACCESS_ACL_DENIED, which are triggered when a policy allows or denies access for a user. For example:

    when ACCESS_ACL_ALLOWED {
      if { [HTTP::uri] contains "/login" } {
        log local0. 'User [ACCESS::session data get "session.login.last.username"] was allowed by the access policy'
      }
    } 
     
    when ACCESS_ACL_DENIED {
      if { [HTTP::uri] contains "/login" } {
        log local0. 'User [ACCESS::session data get "session.login.last.username"] was denied by the access policy'
      }
    }

    There are other result parts that you could log, too. This is only an example. Even still, this is duplicating a built-in function.

    In general, APM iRule events are typically used to do something the product can't do or to augment the way it behaves. For example, if a policy produces a denied result, you might want to perform a custom check of extenuating circumstances unique to your application delivery that might make you allow access in the end.

    As a DevCentral "newbie," might I suggest you take a peek at our free self-paced Getting Started with APM course. In addition, the Configuring BIG-IP APM: Access Policy Manager instructor-led course provides insight on managing access policies with BIG-IP APM.

  • I'm not an APM expert but you should be able to use a logging profile that publishes to one or more high-speed logging destinations, as you need. You can customize what gets logged. Have you checked out the BIG-IP APM manuals on AskF5, specifically on Logging and Reporting? Here's a link to the one for BIG-IP v15.1. (Other releases have their own manuals.)

    • J_Aldrich's avatar
      J_Aldrich
      Icon for Altostratus rankAltostratus

      Thanks for your help . Turns out I needed to use "when ACCESS_POLICY_COMPLETED" instead of "when ACCESS_POLICY_STARTED". Then everything worked as it should.

       

  • Thanks for the reply. Unfortunately, I am still having issues. There are no ACLs, so neither the "when ACCESS_ACL_ALLOWED" or "when ACCESS_ACL_DENIED" produce any results.

     

    I tried this:

     

    when ACCESS_POLICY_AGENT_EVENT {

    log local0. "Result = [ACCESS::session data get session.policy.result]"

    log local0. "State = [ACCESS::session data get session.state]"

    }

    }

     

    But it also returns the same "not_started" message.

     

    I realize the APM log already provides this information, but I have been asked to provide all the information to be displayed in one concise log message in the LTM log.

     

    I reviewed some of the APM training, but I was unable to find anything relating to this specific issue.

     

    Is this even possible?

     

    Another idea of mine is to trigger an event when the user hits the my.policy page that says "Access was denied by the access policy." Any thoughts?

     

     

     

     

     

     

  • Ah, such a simple solution. Why didn’t I think of it? 🙂