Forum Discussion

Nimbostratus

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:

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 | | 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:

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

12 Replies

nitass
Employee
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
Nimbostratus
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

Employee

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
Nimbostratus
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
Nimbostratus
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.
nitass
Employee
Feb 06, 2012
can you post your entire irule?
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
Nimbostratus
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
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
Nimbostratus
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!