Forum Discussion

huli_huli_37457's avatar
huli_huli_37457
Icon for Nimbostratus rankNimbostratus
Feb 04, 2012

Table timeout/lifetime Not Reflected in -count

Howdy!

 

 

I am attempting to build an IRULE that functions as a gate keeper, limiting the number of active sessions at any given point in time.

 

 

 

I am using a sub-table to manage each session. When the count of keys is less than some threshold, the request is allowed, a UUID is established, a cookie is set with the UUID, and a table entry is created using the UUID as the key and with timeout/lifetime X. If that same UUID accesses a certain URI, the timeout/lifetime is reset to Y. Otherwise, the table entry is expected to timeout, thus lowering the count of keys.

 

 

 

Under a controlled environment, this works as expected, and I can predictably identify when a session is active and/or blocked. However, within production and under load, the count of keys never goes down. Here's the kicker: if I iterate over the keys and calculate the count myself, the value aligns with expectations! Unfortunately this technique performs poorly and impedes functionality.

 

 

 

Below is an excerpt from the log, where:

 

 

 

[Dis]Allowing request: [Domain] | [URI Milestone] | [Manual Key Count] v [Table -count] | [Has UUID] | [Remaining Lifetime] | [UUID] | [Is Bot]

 

 

 

Sat Feb 4 14:46:11 CST 2012 info local/tmm3 tmm3[6172] Rule IRULE_GateKeeper : Allowing request: www.mywebsite.com | Default | 119 v 16355 | 1 | 318 | UUID9 | -1

 

Sat Feb 4 14:46:11 CST 2012 info local/tmm2 tmm2[6171] Rule IRULE_GateKeeper : Allowing request: www.mywebsite.com | Default | 119 v 16355 | 0 | 152 | 0 | -1

 

Sat Feb 4 14:46:11 CST 2012 info local/tmm3 tmm3[6172] Rule IRULE_GateKeeper : Allowing request: www.mywebsite.com | Default | 119 v 16355 | 0 | 152 | 0 | 6

 

Sat Feb 4 14:46:12 CST 2012 info local/tmm3 tmm3[6172] Rule IRULE_GateKeeper : Allowing request: www.mywebsite.com | Default | 117 v 16355 | 0 | 151 | 0 | 31

 

Sat Feb 4 14:46:12 CST 2012 info local/tmm3 tmm3[6172] Rule IRULE_GateKeeper : Allowing request: www.mywebsite.com | Default | 117 v 16355 | 0 | 151 | 0 | -1

 

Sat Feb 4 14:46:12 CST 2012 info local/tmm3 tmm3[6172] Rule IRULE_GateKeeper : Allowing request: www.mywebsite.com | Default | 117 v 16355 | 0 | 151 | 0 | -1

 

Sat Feb 4 14:46:12 CST 2012 info local/tmm3 tmm3[6172] Rule IRULE_GateKeeper : Allowing request: www.mywebsite.com | | 117 v 16355 | 1 | | UUID7 | -1

 

Sat Feb 4 14:46:12 CST 2012 info local/tmm3 tmm3[6172] Rule IRULE_GateKeeper : Allowing request: www.mywebsite.com | | 118 v 16356 | 1 | | UUID5 | -1

 

Sat Feb 4 14:46:12 CST 2012 info local/tmm tmm[6169] Rule IRULE_GateKeeper : Allowing request: www.mywebsite.com | Default | 119 v 16357 | 1 | 320 | UUID5 | -1

 

Sat Feb 4 14:46:13 CST 2012 info local/tmm3 tmm3[6172] Rule IRULE_GateKeeper : Allowing request: www.mywebsite.com | Default | 118 v 16357 | 0 | 150 | 0 | 31

 

Sat Feb 4 14:46:13 CST 2012 info local/tmm tmm[6169] Rule IRULE_GateKeeper : Allowing request: www.mywebsite.com | Default | 118 v 16357 | 1 | 310 | UUID3 | -1

 

Sat Feb 4 14:46:13 CST 2012 info local/tmm3 tmm3[6172] Rule IRULE_GateKeeper : Allowing request: www.mywebsite.com | Default | 118 v 16357 | 1 | 303 | UUID1 | -1

 

Sat Feb 4 14:46:13 CST 2012 info local/tmm tmm[6169] Rule IRULE_GateKeeper : Allowing request: www.mywebsite.com | Default | 118 v 16357 | 1 | 205 | UUID0 | -1

 

 

 

 

Note the massive discrepancy between the two session key counts.

 

 

 

Below is the code...

 

 

 

Making the table entry:

 

 

 

; declare session table values

 

set table_uri "Default"

 

set table_timeout $tier1_timeout

 

set table_mode "add"

 

 

 

if {[HTTP::path] contains "OrderReceipt" } {

 

; if request URI corresponds with Order Receipt page

 

set table_uri "Receipt"

 

set table_timeout $tier4_timeout

 

set table_mode "set"

 

} elseif {[HTTP::uri] contains "Checkout"} {

 

; if request URI corresponds with Checkout action

 

set table_uri "Checkout"

 

set table_timeout $tier3_timeout

 

set table_mode "set"

 

} elseif {[HTTP::path] contains "AddToCart"} {

 

; if request URI corresponds with an Add to Cart action

 

set table_uri "Add2Cart"

 

set table_timeout $tier2_timeout

 

set table_mode "set"

 

}

 

 

 

table $table_mode -subtable $table_subname $client_id $table_uri $table_timeout $table_timeout

 

 

 

 

Calculating the key count:

 

 

 

set session_count_native [table keys -subtable $table_subname -count]

 

 

 

set session_count 0

 

foreach { key } [table keys -subtable $table_subname] {

 

set key_timestamp [table lookup -notouch -subtable $table_subname $key]

 

incr session_count 1

 

}

 

 

 

 

 

 

And the log entry above:

 

 

 

log local0. "Allowing request: $host | $session_value | $session_count v $session_count_native | $has_uuid | $session_life | $uuid | $is_bot "

 

 

 

 

 

 

The F5 seems like the simplest and most appropriate layer to enforce this type of logic. Anything you can offer to help troubleshoot this concern will be GREATLY APPRECIATED.

 

 

 

Thank you

 

 

 

application delivery
dev
devops
iRules
  • nitass's avatar
    nitass
    Icon for Employee rankEmployee
    Feb 05, 2012
    set session_count 0

     

    foreach { key } [table keys -subtable $table_subname] {

     

    set key_timestamp [table lookup -notouch -subtable $table_subname $key]

     

    incr session_count 1

     

    }just wonder if this is all calculation key count code. it seems session_count must be equal to a number of key in subtable (since it is increased in each loop. how come is result different??
  • huli_huli_37457's avatar
    huli_huli_37457
    Icon for Nimbostratus rankNimbostratus
    Feb 05, 2012
    Thanks for the reply! My assumption is that table -count considers all entries irrespective of timeout/lifetime whereas table -keys returns only active entries. And I think this is why performance slows over time because the table is allowed to grow unchecked. Is this a bug that is addressed with a later version? What would be ideal is to attach an event to the table key expiration so that a local counter could be maintained.
  • nitass's avatar
    nitass
    Icon for Employee rankEmployee
    Feb 05, 2012
    My assumption is that table -count considers all entries irrespective of timeout/lifetime i do not think so. 

    [root@ve1023:Active] config  b rule myrule list
rule myrule {
   when HTTP_REQUEST {
        table set -subtable test "1.1.1.1" "11111" 1 indef
        table set -subtable test "2.2.2.2" "22222" indef indef
        table set -subtable test "3.3.3.3" "33333" indef indef
        log local0. "\[table key -subtable test\]: [table key -subtable test]"
        log local0. "\[table key -subtable test -count\]: [table key -subtable test -count]"
        after 2000
        log local0. "after 2000 ms"
        log local0. "\[table key -subtable test\]: [table key -subtable test]"
        log local0. "\[table key -subtable test -count\]: [table key -subtable test -count]"
}
}

[root@ve1023:Active] config  cat /var/log/ltm
Feb  5 06:31:23 local/tmm info tmm[4369]: Rule myrule HTTP_REQUEST: [table key -subtable test]: 2.2.2.2 3.3.3.3 1.1.1.1
Feb  5 06:31:23 local/tmm info tmm[4369]: Rule myrule HTTP_REQUEST: [table key -subtable test -count]: 3
Feb  5 06:31:25 local/tmm info tmm[4369]: Rule myrule HTTP_REQUEST: after 2000 ms
Feb  5 06:31:25 local/tmm info tmm[4369]: Rule myrule HTTP_REQUEST: [table key -subtable test]: 2.2.2.2 3.3.3.3
Feb  5 06:31:25 local/tmm info tmm[4369]: Rule myrule HTTP_REQUEST: [table key -subtable test -count]: 2
  • huli_huli_37457's avatar
    huli_huli_37457
    Icon for Nimbostratus rankNimbostratus
    Feb 05, 2012
    Thanks again for the reply. As noted everything works as expected within a controlled environment and I predictably can identify when a session (or table entry) will expire. Things break down when the rule is executed against a production environment with load. is there anything more I can/should do to troubleshoot and/or provide evidence of what I am experiencing?
  • huli_huli_37457's avatar
    huli_huli_37457
    Icon for Nimbostratus rankNimbostratus
    Feb 05, 2012
    And for what its worth, I see that

     

     

    set session_count_native [table keys -subtable $table_subname -count]

     

    set session_count_length [llength [table keys -subtable $table_subname]]

     

     

    $session_count_native and $session_count_length are not equal, even though I would expect them to be. I worry that the overhead associated with calculating $session_count_length is too great for my application, but certainly better than my previous approach of iterating over the list and incrementing a counter.
  • spark_86682's avatar
    spark_86682
    Historic F5 Account
    Feb 06, 2012
    So, there are several things that could be going on here. Without typing up a whole diagnostic tree to go down, let's see if we can eliminate one of the most common problems we've run into which could be causing this behavior. Specifically, this behavior could be evidence that you're hitting ID 247874, which happens because there is some problem with the HA channel between boxes. What version are you on? By any chance is your "controlled environment" BIG-IP configured as a standalone box, but your "production environment" BIG-IP configured as HA/failover? If your production box is set up for HA, then please double-check all of the HA configuration, especially peer IP addresses. If the problem remains, then the most definitive way to test for that ID is to set the "StateMirror.MirrorSessions" DB variable to "disable" on the boxes demonstrating the problem and then rebooting them. Perhaps you could try that during a maintenance window. If the problem goes away, you are definitely hitting ID 247874.
  • huli_huli_37457's avatar
    huli_huli_37457
    Icon for Nimbostratus rankNimbostratus
    Feb 06, 2012
    Thank you Spark for the reply!!

     

     

    - We are operating in a High Availability environment but we haven’t seen any issues where there is a connection problem with the peer.

     

    - The version is BIG-IP 10.2.3 Build 123.0 Hotfix HF1

     

    - The test was also performed in the HA environment - actually, the same environment, just associated with a test VS

     

    - Is this what you're referring to? http://support.f5.com/kb/en-us/solutions/public/12000/300/sol12370.html?sr=19166086

     

  • spark_86682's avatar
    spark_86682
    Historic F5 Account
    Feb 06, 2012
    OK, so you are on an affected version then, and you're using HA, so you could be hitting that ID. That SOL is what I'm referring to yes, but while the problem described there is also a problem you may run into, that ID could also cause the behavior you're seeing. Some more questions for you:

     

     

    1) In your controlled environment, what is the highest number of entries you put in a subtable where you see this problem?

     

     

    2) In your log statements above, you have several consecutive lines which show counts of "119 v 16355". Are these all on the same subtable, or are those counts from different subtables?

     

     

    3) Could you change your iRules to do a manual count first, and then do a "-count" immediately after? I'm not suggesting that as a long-term solution, but if you do that and you still see the problem, then that is very strong evidence you're either hitting ID 247874 or some other issue we haven't seen before.
  • huli_huli_37457's avatar
    huli_huli_37457
    Icon for Nimbostratus rankNimbostratus
    Feb 06, 2012

     

    1. Less than a handful. It never crossed my mind that we would experience different behavior under load.

     

     

    2/3. The counts are from the same table, using two (or three) different methods to arrive at the value:

     

     

    a. set session_count_native [table keys -subtable $table_subname -count]

     

    b. set session_count_length [llength [table keys -subtable $table_subname]]

     

    c. set session_keys [table keys -subtable $table_subname] >> and loop over the keys incrementing a counter

     

     

    In the example above "119 v 16355" equates to [b,c] v [a].

     

     

     

    Sounds like our best option is to upgrade to the latest/greatest version. Are there any known issues/incompatibilities between the two versions?

     

     

     

    Thanks again Spark for the amazing support!