Thursday, March 25, 2010

F5 Persistence and my 6 week battle with support

We've been having issues with persistence on our F5's since we launched our new product. We have tried many different ways of trying to get our clients to stick on a server. Of course the first step was using a standard cookie persistence which the F5 was injecting. All of our products which use SSL is being terminated on the F5, which makes cookie work fine even for SSL traffic. After we started seeing clients going to many servers, we figured it would be safe to use a JSESSIONID cookie which is a standard Java application server cookie that is always unique per session. We implemented the following Irule (slightly modified in order to get more logging):

http://devcentral.f5.com/Default.aspx?tabid=53&view=topic&postid=1171255 (registration is free)

when HTTP_REQUEST {

# Check if there is a JSESSIONID cookie

if {[HTTP::cookie "JSESSIONID"] ne ""}{

# Persist off of the cookie value with a timeout of 2 hours (7200 seconds)

persist uie [string tolower [HTTP::cookie "JSESSIONID"]] 7200

# Log that we're using the cookie value for persistence and the persistence key if it exists.

log local0. "[IP::client_addr]:[TCP::client_port]: Request to [HTTP::uri] on server [LB::server] with cookie: [HTTP::cookie value JSESSIONID]"

} else {

# Parse the jsessionid from the path

set jsess [findstr [string tolower [HTTP::path]] "jsessionid=" 11]

# Use the jsessionid from the path for persisting with a timeout of 2 hours (7200 seconds)

if { $jsess != "" } {

persist uie $jsess 7200

# Log that we're using the path jessionid for persistence and the persistence key if it exists.

log local0. "[IP::client_addr]:[TCP::client_port]: Request to [HTTP::uri] on server [LB::server] used persistence record from path: [persist lookup uie $jsess]"

}

}

}

when HTTP_RESPONSE {

# Check if there is a jsessionid cookie in the response

if {[HTTP::cookie "JSESSIONID"] ne ""} {

# Persist off of the cookie value with a timeout of 2 hours (7200 seconds)

persist add uie [string tolower [HTTP::cookie "JSESSIONID"]] 7200

            # Log Response

log local0. "[IP::client_addr]:[TCP::client_port]: Request to server [LB::server] with cookie: [HTTP::cookie value JSESSIONID]. Added persistence record from cookie: [persist lookup uie [string tolower [HTTP::cookie "JSESSIONID"]]]"

}

}

when LB_SELECTED {

log "From [IP::client_addr] to physical server [LB::server] the cookie JSESSIONID is [HTTP::cookie "JSESSIONID"] URI JESSIONID is [findstr [string tolower [HTTP::path]] "jsessionid=" 11] "

}


 

We've replicated and done 3 rounds of packet captures, and you can always see the issue in the logging from the irule above:

Mar 21 01:14:25 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63231: Request to /images/mfg/icons/search_cross.png on server -http-pool x.x.x.19 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:14:25 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63229: Request to /images/mfg/icons/icon_largemessages.png on server -http-pool BACKENDSUBNET.19 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:14:25 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63228: Request to /images/mfg/icons/icon_clock.png on server -http-pool BACKENDSUBNET.19 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:14:25 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63231: Request to /images/mfg/icons/icon_largequotes.png on server -http-pool BACKENDSUBNET.19 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:14:25 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63233: Request to /images/mfg/icons/icon_largendas.png on server -http-pool BACKENDSUBNET.19 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:14:25 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63230: Request to /images/mfg/icons/icon_largebluestar.png on server -http-pool BACKENDSUBNET.19 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:14:25 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63232: Request to /mfg/scripts/search/search.js on server -http-pool BACKENDSUBNET.19 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:14:25 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63235: Request to /favicon.ico on server -http-pool 0 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:14:25 tmm tmm[1629]: 01220002:6: Rule JSESSION_iRule_withlogging <LB_SELECTED>: From CLIENTIP to physical server -http-pool BACKENDSUBNET.19 80 the cookie JSESSIONID is abcND0QYKjeOCczB8c_Ds URI JESSIONID is

Mar 21 01:14:25 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63236: Request to /servlet/mfg.Controller?time=1269130074065&pmId=1001&act=1154 on server -http-pool 0 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:14:25 tmm tmm[1629]: 01220002:6: Rule JSESSION_iRule_withlogging <LB_SELECTED>: From CLIENTIP to physical server -http-pool BACKENDSUBNET.19 80 the cookie JSESSIONID is abcND0QYKjeOCczB8c_Ds URI JESSIONID is

Mar 21 01:14:25 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63224: Request to /mfg/contactHome.jsp?time=1269130079475&pmId=1154 on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:31 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63247: Request to /servlet/mfg.Controller?time=1269130079686&pmId=1154&act=supplierDisplayAgent&aid=904564&dgrdv=1 on server -http-pool 0 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:31 tmm tmm[1629]: 01220002:6: Rule JSESSION_iRule_withlogging <LB_SELECTED>: From CLIENTIP to physical server -http-pool BACKENDSUBNET.20 80 the cookie JSESSIONID is abcND0QYKjeOCczB8c_Ds URI JESSIONID is

Mar 21 01:15:31 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63247: Request to /mfg/contactHome.jsp?time=1269130145070&pmId=1016 on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:43 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63247: Request to /images/mfg/modalbox/close.gif on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:44 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63247: Request to /servlet/mfg.Controller?time=1269130145287&pmId=1016&act=modal&mtId=800&mLoad=true&aid=904564 on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:44 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63250: Request to /images/bo/design/spinner.gif on server -http-pool 0 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:44 tmm tmm[1629]: 01220002:6: Rule JSESSION_iRule_withlogging <LB_SELECTED>: From CLIENTIP to physical server -http-pool BACKENDSUBNET.20 80 the cookie JSESSIONID is abcND0QYKjeOCczB8c_Ds URI JESSIONID is

Mar 21 01:15:44 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63247: Request to /images/mfg/icons/search_cross.png on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:44 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63250: Request to /images/mfg/icons/doubleDownArrow.png on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:45 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63247: Request to /images/mfg/combo/comboover.gif on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:45 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63250: Request to /images/mfg/combo/combopress.gif on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:46 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63247: Request to /servlet/mfg.ajaxProvider.GetDisciplineProvider;jsessionid=abcND0QYKjeOCczB8c_Ds?time=1269130158059&pmId=1016 on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:46 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63250: Request to /servlet/mfg.ajaxProvider.GetRfqBuyerLocationProvider?time=1269130158059&pmId=1016&sImg=false&sCwor=false on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:46 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63247: Request to /images/mfg/icons/dhtmlTree/iconUnCheckAll.gif on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:46 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63247: Request to /servlet/mfg.ajaxProvider.GetMaterialProvider?time=1269130158060&pmId=1016&sImg=false on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:46 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63250: Request to /images/mfg/combo/combonormal.gif on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:46 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63247: Request to /servlet/mfg.ajaxProvider.GetIndustryProvider?time=1269130158060&pmId=1016&ids= on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:46 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63250: Request to /servlet/mfg.ajaxProvider.GetLanguageProvider?time=1269130158060&pmId=1016&ids= on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds

Mar 21 01:15:47 tmm tmm[1629]: Rule JSESSION_iRule_withlogging <HTTP_REQUEST>: CLIENTIP:63247: Request to /images/mfg/icons/dhtmlTree/folderOpen.gif on server -http-pool BACKENDSUBNET.20 80 with cookie: abcND0QYKjeOCczB8c_Ds


 

The support team cannot figure out why this is, and it's been going on for very long. I will keep updating this as it goes on. The latest saga is that they are blaming it on the SNAT we are using.

http://devcentral.f5.com/Default.aspx?tabid=53&view=topic&postid=813179

http://devcentral.f5.com/Default.aspx?tabid=53&forumid=5&tpage=1&view=topic&postid=86374

F5 can be implemented as the inline gateway or outside of the gateway as a NAT device. We opted for the latter in order to avoid sending unnecessary traffic through the device. We may have to do some testing with it as the gateway and see if it fixes it. It clearly looks like a bug to me. We are running BIG-IP 9.4.5 Build 1049.10 Final, and we're planning on moving to V10 soon.

1 comment:

massage therapist directory MassageRadar.com said...

Adventures of a Technical MasterMind is a good blog for IT geeks.