Forum Discussion
dennypayne
Employee
Jul 16, 2009iRule seems to stop processing
Can anybody spot why this rule might appear to get "stuck" after it assigns the $sessionid variable? It sometimes doesn't get to the next log statement where it logs $serverlist, and it never gets to the following log statement where it logs the $egpslength variable. The ltm log shows whichever previous log statement repeating a number of times, and then the next log statement is the initial one at the beginning of the rule again. Could the append and/or string length commands be getting tripped up somehow by some instances of the values they are trying to manipulate? I'm at a loss...
The rule:
when HTTP_REQUEST {
if {
[HTTP::uri] starts_with "/cobrowse/egps.egint" or [HTTP::uri] starts_with "/cobrowse/egpsa.egint"
}{
log "Cobrowse iRule1 Variable name changed on 12 July starts [HTTP::uri]"
log "Cobrowse iRule1. Cookie count [HTTP::cookie count] [HTTP::cookie names]"
set isagent [HTTP::cookie value "agentCobrowseUser"]
log "Cobrowse iRule1 Agent is $isagent"
if {
$isagent eq "true"
}{
if {
[HTTP::uri] contains "egpssid="
}{
if {
[catch {
set sessionid [findstr [HTTP::uri] "egpssid=" 8 "&"]
} fid]
}{
log "Cobrowse iRule2. Session Id is $sessionid Error is occured while checking sessionid $fid"
}
log "Cobrowse iRule2. Session Id is $sessionid"
append sessionid "X"
set serverlist [HTTP::cookie value "cobrowse_servers"]
log "Cobrowse iRule2. Session Id is $sessionid Server List is $serverlist"
set egpslength [string length $sessionid]
log "Cobrowse iRule2. Session Id is $sessionid Length is $egpslength"
if {
[catch {
set servername [findstr $serverlist $sessionid $egpslength "X"]
} eid]
}{
log "Cobrowse iRule2. Session Id is $sessionid Error is occured at servername $eid"
}
log "Cobrowse iRule2. Session Id is $sessionid Server Name is $servername"
if {
[catch {
set mystatus [LB::status pool COBROWSE1 member $servername 80]
} eeid]
}{
log "Cobrowse iRule2. Session Id is $sessionid Error is occured at status $eeid"
} else {
log "Cobrowse iRule2. Session Id is $sessionid mystatus is $mystatus"
}
if {
[LB::status pool COBROWSE1 member $servername 80] eq "up"
}{
log "Cobrowse iRule2. Session Id is $sessionid Server $servername is up"
node $servername 80
} else {
log "Cobrowse iRule2. Session Id is $sessionid Agent Failover detected"
pool COBROWSE1
}
}
} else {
pool COBROWSE1
}
} elseif {
[HTTP::uri] starts_with "/cobrowse/"
}{
pool COBROWSE1
} else {
pool CONTACTUS1
}
}
And the typical output from /var/log/ltm:
Jul 15 22:43:14 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1 Variable name changed on 12 July starts
/cobrowse/egpsa.egint?egpscmd=pinguser&egpssid=5643&egpsuid=1_1437&egpsi18nid=enUS
Jul 15 22:43:14 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1. Cookie count 26 BrowserNavData
RBSLogon_sToken USCCookie BIGipServerCONTACTUS1 ASPSESSIONIDASBATAST eGain_eService_JSESSIONID cobrowse_servers egp
l_uac_chatlistColsWdNames_activity agentCobrowseUser BIGipServerCOBROWSE1 jsessioncobrowse_prodcimcb1w isSameDomain egpsi18nid
BrowserNavData RBSLogon_sToken USCCookie BIGipServerCONTACTUS1 ASPSESSIONIDASBATAST eGain_eService_JSESSIONID
cobrowse_servers egpl_uac_chatlistColsWdNames_activity agentCobrowseUser BIGipServerCOBROWSE1 jsessioncobrowse_prodcimcb1w
isSameDomain egpsi18nid
Jul 15 22:43:14 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1 Agent is true
Jul 15 22:43:14 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule2. Session Id is 5643
Jul 15 22:43:17 tmm tmm[2017]: 01220002: repeated 5 times
Jul 15 22:43:22 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1 Variable name changed on 12 July starts
/cobrowse/egps.egint?egpscmd=join&egpsi18nid=enUS&egpssid=5645&egpssubscriberid=1_1437&egpsusesunjvm=undefi
ned
Jul 15 22:43:22 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1. Cookie count 13 BrowserNavData
RBSLogon_sToken USCCookie BIGipServerCONTACTUS1 ASPSESSIONIDASBATAST eGain_eService_JSESSIONID cobrowse_servers egp
l_uac_chatlistColsWdNames_activity agentCobrowseUser BIGipServerCOBROWSE1 jsessioncobrowse_prodcimcb1w isSameDomain egpsi18nid
Jul 15 22:43:22 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1 Agent is true
Jul 15 22:43:22 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule2. Session Id is 5645
Jul 15 22:43:22 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule2. Session Id is 5645X Server List is
5643X192.168.114.135X5645X192.168.114.135
Jul 15 22:43:23 tmm tmm[2017]: 01220002: repeated 49 times
Jul 15 22:43:31 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1 Variable name changed on 12 July starts
/cobrowse/egpsa.egint?egpscmd=getrid&egpssid=5645&egpsuid=1_1437&egpsi18nid=enUS
Jul 15 22:43:32 tmm tmm[2017]: 01220002: repeated 13 times
Jul 15 22:43:32 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1 Variable name changed on 12 July starts
/cobrowse/egps.egint?egpscmd=running&egpssid=5645&egpsuid=1_1437&egpsi18nid=enUS
Jul 15 22:43:35 tmm tmm[2017]: 01220002: repeated 145 times
Jul 15 22:43:35 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1 Variable name changed on 12 July starts
/cobrowse/egps.egint?egpscmd=running&egpssid=5645&egpsuid=1_1437&egpsrid=2009_07_15_22_21_13_242346&egpsfra
meid=&egpswindowid=1
Jul 15 22:43:35 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1. Cookie count 13 BrowserNavData
RBSLogon_sToken USCCookie BIGipServerCONTACTUS1 ASPSESSIONIDASBATAST eGain_eService_JSESSIONID cobrowse_servers egp
l_uac_chatlistColsWdNames_activity agentCobrowseUser BIGipServerCOBROWSE1 jsessioncobrowse_prodcimcb1w isSameDomain egpsi18nid
Jul 15 22:43:35 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1 Agent is true
Jul 15 22:43:35 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule2. Session Id is 5645
Jul 15 22:43:35 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule2. Session Id is 5645X Server List is
5643X192.168.114.135X5645X192.168.114.135
Jul 15 22:43:38 tmm tmm[2017]: 01220002: repeated 169 times
Jul 15 22:43:38 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1 Variable name changed on 12 July starts
/cobrowse/egps.egint?egpscmd=running&egpssid=5645&egpsuid=1_1437&egpsrid=2009_07_15_22_21_13_242362&egpsfra
meid=&egpswindowid=1
Jul 15 22:43:38 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1. Cookie count 13 BrowserNavData
RBSLogon_sToken USCCookie BIGipServerCONTACTUS1 ASPSESSIONIDASBATAST eGain_eService_JSESSIONID cobrowse_servers egp
l_uac_chatlistColsWdNames_activity agentCobrowseUser BIGipServerCOBROWSE1 jsessioncobrowse_prodcimcb1w isSameDomain egpsi18nid
Jul 15 22:43:38 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1 Agent is true
Jul 15 22:43:38 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule2. Session Id is 5645
Jul 15 22:43:38 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule2. Session Id is 5645X Server List is
5643X192.168.114.135X5645X192.168.114.135
Jul 15 22:43:41 tmm tmm[2017]: 01220002: repeated 211 times
Jul 15 22:43:41 tmm tmm[2017]: 01220002:6: Rule CIM_Test1 : Cobrowse iRule1 Variable name changed on 12 July starts
/cobrowse/egps.egint?egpscmd=running&egpssid=5645&egpsuid=1_5645cust1034&egpsrid=2009_07_15_22_21_13_242373
&egpsfID=&egpsi18nid=English-US&egpsChkUid=1&egpswindowid=1&rnd=4
6 Replies
- hoolio
Cirrostratus
Hey Denny,
I don't see anything obvious as it doesn't seem like there is anything that would stall the connections. But it's a little difficult to follow the logs.
Does the issue happen during single user testing or just under load? Can you add the client IP and port to the log statements?
Aaron - dennypayne
Employee
I think it's just single user, but I'm not 100% positive on that. I can probably get IP/port info added during the next test cycle though.
I also just noticed that it's showing the "Cookie Count" in one of the log entries as 26, isn't there a browser limitation on the number of cookies that can be used in a session (20?). Looks like some cookies are getting duplicated too, that may be part of the problem.
Denny - spark_86682Historic F5 AccountI think this could be because you are using bare "log" statements instead of specifying at least a facility (as in "log local0."). The wiki page on the log command (http://devcentral.f5.com/wiki/default.aspx/iRules/log.html) has more details on this behavior.
- hoolio
Cirrostratus
That makes sense Spark for the 'repeated X times' messages. Is there a problem with traffic handling or just with the logging?
Aaron - spark_86682Historic F5 AccountIt only changes the logging behavior; it shouldn't have any effect on iRule execution.
- Rakesh_Shah_796
Nimbostratus
Me and Denny are working together on this issue.
yes, there is traffic shaping issue. And for troubleshooting these log statements were inserted.
We tested this iRule with ver 9.3.1 and found it works!
thanks
Rakesh
====
Help guide the future of your DevCentral Community!
What tools do you use to collaborate? (1min - anonymous)Recent Discussions
Related Content
DevCentral Quicklinks
* Getting Started on DevCentral
* Community Guidelines
* Community Terms of Use / EULA
* Community Ranking Explained
* Community Resources
* Contact the DevCentral Team
* Update MFA on account.f5.com
Discover DevCentral Connects