iRule seems to stop processing

Question

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 "&amp;"] 
 } 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&amp;egpssid=5643&amp;egpsuid=1_1437&amp;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&amp;egpsi18nid=enUS&amp;egpssid=5645&amp;egpssubscriberid=1_1437&amp;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&amp;egpssid=5645&amp;egpsuid=1_1437&amp;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&amp;egpssid=5645&amp;egpsuid=1_1437&amp;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&amp;egpssid=5645&amp;egpsuid=1_1437&amp;egpsrid=2009_07_15_22_21_13_242346&amp;egpsfra   
 meid=&amp;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&amp;egpssid=5645&amp;egpsuid=1_1437&amp;egpsrid=2009_07_15_22_21_13_242362&amp;egpsfra   
 meid=&amp;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&amp;egpssid=5645&amp;egpsuid=1_5645cust1034&amp;egpsrid=2009_07_15_22_21_13_242373   
 &amp;egpsfID=&amp;egpsi18nid=English-US&amp;egpsChkUid=1&amp;egpswindowid=1&amp;rnd=4

hooleylist · Answer

Hey Denny, 
&nbsp;  
&nbsp; 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.   
&nbsp;  
&nbsp; Does the issue happen during single user testing or just under load?  Can you add the client IP and port to the log statements? 
&nbsp;  
&nbsp; Aaron

dennypayne · Answer

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. 
&nbsp;  
&nbsp; 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. 
&nbsp;  
&nbsp; Denny

spark_86682 · Answer

I 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.

hooleylist · Answer

That makes sense Spark for the 'repeated X times' messages.  Is there a problem with traffic handling or just with the logging? 
&nbsp;  
&nbsp; Aaron

spark_86682 · Answer

It only changes the logging behavior; it shouldn't have any effect on iRule execution.

Forum Discussion

iRule seems to stop processing

6 Replies

Recent Discussions

Port Group on F5OS network setting

F5Access | MacOS Sonoma

Rewrite uri translation not working

Chrome V 124+ on MacOS - Virtual Server Access Issue

Transaction looks successful but file not downloading

Related Content

iRule Processing query

qkview process stuck

iRule match & processing exit

Knowledge sharing: F5 Software Upgrade/RMA process

STREAM::expression doesn't seem to work