Forum Discussion

Ryan_126004's avatar
Ryan_126004
Icon for Nimbostratus rankNimbostratus
Jun 06, 2014

table command causing abort of rule event HTTP_REQUEST

Hello everyone,

This is my first dig into iRules, and I'm hitting an issue with the table command that is aborting my rule. I'm essentially trying to rate limit requests per URI per ASPNET Session ID. I've been working with the iRule for a couple days, so I know it's not at its best and has excessive logging (for the purposes of figuring this out). I'm testing with a backend server that doesn't use ASP, so I'm setting it statically in the iRule as a failsafe for now. I'm building that up now for testing.. but hit some snags.

The main issue is the table command aborting the rule execution. I was originally putting many of the table lookups directly into the if statements, but I was able to resolve an abort earlier in the rule by setting to a variable first.

Here are the logs:

 

[admin@LTM1:ModuleNotLicensed:Active:Standalone] ~  tail /var/log/ltm
Jun  6 11:07:23 LTM1 info tmm1[8579]: 01220009:6: Pending rule event HTTP_REQUEST aborted for 192.168.21.102:58079->10.202.20.170:80 (listener: /Common/Drupal_HTTP)
Jun  6 11:07:23 LTM1 info tmm[8579]: Rule /Common/JSESSIONRateLimit : iRule_Rate-Limiter: HTTP_REQUEST Matched
Jun  6 11:07:23 LTM1 info tmm[8579]: Rule /Common/JSESSIONRateLimit : iRule_Rate-Limiter: No session cookie found. Quitting..
Jun  6 11:07:23 LTM1 info tmm[8579]: Rule /Common/JSESSIONRateLimit : iRule_Rate-Limiter: Got URI, /drupal/themes/garland/images/bg-content-right.png, making key: session1_/drupal/themes/garland/images/bg-content-right.png
Jun  6 11:07:23 LTM1 info tmm[8579]: 01220009:6: Pending rule event HTTP_REQUEST aborted for 192.168.21.102:58080->10.202.20.170:80 (listener: /Common/Drupal_HTTP)
Jun  6 11:07:23 LTM1 info tmm1[8579]: Rule /Common/JSESSIONRateLimit : iRule_Rate-Limiter: HTTP_REQUEST Matched
Jun  6 11:07:23 LTM1 info tmm1[8579]: Rule /Common/JSESSIONRateLimit : iRule_Rate-Limiter: No session cookie found. Quitting..
Jun  6 11:07:23 LTM1 info tmm1[8579]: Rule /Common/JSESSIONRateLimit : iRule_Rate-Limiter: Got URI, /drupal/themes/garland/images/bg-content-right.png, making key: session1_/drupal/themes/garland/images/bg-content-right.png
Jun  6 11:07:23 LTM1 info tmm1[8579]: Rule /Common/JSESSIONRateLimit : iRule_Rate-Limiter: Matched second else.. not following conditionals.
Jun  6 11:07:23 LTM1 info tmm1[8579]: 01220009:6: Pending rule event HTTP_REQUEST aborted for 192.168.21.102:58081->10.202.20.170:80 (listener: /Common/Drupal_HTTP)
`

Here is the rule:

`when HTTP_REQUEST {
    log local0. "iRule_Rate-Limiter: HTTP_REQUEST Matched"
    set maxReqs 5
    set cooldownTimer 30
    set sampleTimer 30
    set timeout 30

    if { [HTTP::cookie exists "ASP.NET_SessionId"] } {
        set aspid [HTTP::cookie ASP.NET_SessionId]
        log local0. "iRule_Rate-Limiter: SESSION Cookie present: $aspid"
    } else {
        log local0. "iRule_Rate-Limiter: No session cookie found. Quitting.."
        pool Drupal_Pool
        event HTTP_REQUEST disable
        set aspid "session1"
    } 

    set reqURI [string tolower [HTTP::uri]] 
    set key "$aspid"
    append key "_$reqURI"

    log local0. "iRule_Rate-Limiter: Got URI, $reqURI, making key: $key"

    set onCooldown [table lookup -subtable "Cooldowns" $key]
    if { $onCooldown != "" } {
        log local0. "iRule_Rate-Limiter: Key: $key is already on cooldown, sending HTTP:429 status code."
        HTTP::respond 429
    } else {
        log local0. "iRule_Rate-Limiter: Matched second else.. not following conditionals."

        set currCount [table add $key 1]
        if { $currCount == "" } {
            table set $key 1 $timeout $sampleTimer
            log local0. "iRule_Rate-Limiter: First attempt for $key, adding to table for tracking."
        } else {    
            if { ($currCount <= $maxReqs) } {
                table incr $key 1
                incr currCount
                log local0. "iRule_Rate-Limiter: $key not on timeout, but not first request. Incrementing count to $currCount in session table."
            } else {
                HTTP::respond 429
                table set -subtable "Cooldowns" $key "yes" $timeout $cooldownTimer
                log local0. "iRule_Rate-Limiter: $key triggered cooldown with $currCount attempts. Adding to cooldown table."
            }
        }  
    }
}

 

Note that the rule is aborting at this line of code (line 31):

set currCount [table add $key 1]

 

Any help here is greatly appreciated, as I can't find anything outlining why this occurs. It's a small rule, and a simple lookup so I don't see why it would cause the rule to suspend indefinitely.

Thanks! Ryan

application delivery
deployment
devops
iRules
LTM
session
table
  • nitass's avatar
    nitass
    Icon for Employee rankEmployee
    Jun 08, 2014

    Pending rule event HTTP_REQUEST aborted for ... (listener: /Common/Drupal_HTTP)

    i may be wrong but i think it means connection is terminated (for whatever reason) before irule is complete.

    by the way, these are my comments.

    1) for static variable (e.g. maxReqs, cooldownTimer, sampleTimer, timeout),

    static

    https://clouddocs.f5.com/api/irules/static.html

    2) in No session cookie found. Quitting section, you may use "return" to exit the current event. event disable does not exit from the event.

    event

    https://clouddocs.f5.com/api/irules/event.html

     

     irule

[root@ve11a:Active:In Sync] config  tmsh list ltm rule qux
ltm rule qux {
    when HTTP_REQUEST {
  log local0. "priority 500: before"
  event HTTP_REQUEST disable
  log local0. "priority 500: after"
}
when HTTP_REQUEST priority 600 {
  log local0. "priority 600"
}
when HTTP_RESPONSE {
  log local0. "priority 500"
}
}

 /var/log/ltm

[root@ve11a:Active:In Sync] config  tail -f /var/log/ltm
Jun  8 11:45:34 ve11a info tmm[9801]: Rule /Common/qux HTTP_REQUEST: priority 500: before
Jun  8 11:45:34 ve11a info tmm[9801]: Rule /Common/qux HTTP_REQUEST: priority 500: after
Jun  8 11:45:35 ve11a info tmm[9801]: Rule /Common/qux HTTP_RESPONSE: priority 500

     

    3) in set currCount [table add $key 1] section, when will table add return null?

    table

    https://clouddocs.f5.com/api/irules/table.html

    • Ryan_126004's avatar
      Ryan_126004
      Icon for Nimbostratus rankNimbostratus
      Jun 08, 2014
      Thanks for the feedback on static variables and return versus event commands. I'll adjust my rule. If the rule is being aborted because the connection is terminated before it completes execution, then.. I'm a bit confused. Without the iRule, the web page loads just fine. Would this also be if the HTTP request completes before the rule is completely executed? When I access the server with the iRule in place, I get no response at all. Is there maybe a better event to trigger this on that would prevent these issues? I'm essentially trying to stop the connection to the backend server and return HTTP 429 is it hits too many requests per URI over 30 seconds. The currCount would return 0 if it's the first attempt at that URI for the current ASPNET Session ID in the last 30 seconds.
  • nitass's avatar
    nitass
    Icon for Employee rankEmployee
    Jun 08, 2014

    The currCount would return 0 if it's the first attempt at that URI for the current ASPNET Session ID in the last 30 seconds.

    isn't it one? anyway, it is not going to be null, is it?

    Returns the entry's value after the set operation is complete.

    Would this also be if the HTTP request completes before the rule is completely executed?

    i do not think http request is complete because if it is, irule should be complete too, shouldn't it?

    have you tried tcpdump? tcpdump may show what happens on the connection.

     

    • Ryan_126004's avatar
      Ryan_126004
      Icon for Nimbostratus rankNimbostratus
      Jun 08, 2014
      Good point.. it would always return 1. I originally was using just table set, but changed it to see if the abort would stop occurring. My understanding was that it wouldn't complete without the iRule, either, but wanted to ask just to be sure. I have done a tcpdump, and the connection looks completely normal. No early terminations, fins, rst, etc.. Again, everything is fine without the iRule.. could something in the iRule be causing this? It doesn't seem like the rule is hitting any piece where it actually interferes with the connection before it is aborting.
  • nitass's avatar
    nitass
    Icon for Employee rankEmployee
    Jun 08, 2014

    I have done a tcpdump, and the connection looks completely normal. No early terminations, fins, rst, etc..

    you checked connection matching the log, didn't you? for example, in the following log, you saw response to client 192.168.21.102 port 58079, didn't you?

     

    Jun  6 11:07:23 LTM1 info tmm1[8579]: 01220009:6: Pending rule event HTTP_REQUEST aborted for 192.168.21.102:58079->10.202.20.170:80 (listener: /Common/Drupal_HTTP)

     

    • Ryan_126004's avatar
      Ryan_126004
      Icon for Nimbostratus rankNimbostratus
      Jun 08, 2014
      Yes, this is also a lab LTM, so it was the only connection to the box other than my SSH session.
    • nitass's avatar
      nitass
      Icon for Employee rankEmployee
      Jun 08, 2014
      in that case, i think it may be good to open a support case.
    • Ryan_126004's avatar
      Ryan_126004
      Icon for Nimbostratus rankNimbostratus
      Jun 17, 2014
      I contacted support. It turns out the event disable was causing this problem even though that conditional wasn't matching and the rule wasn't being aborted until after that line in the rule. I removed it and it works fine.