Forum Discussion
sriramgd_111845
Nimbostratus
NimbostratusLogging in case of http 404 and 50* responses
We use an F5 in our production environment. We use one big iRule to route traffic to the relevant pools based on the url etc.
Recently we have started using some limited amount of on-the-grid deployments to allow for faster releases. The problem with this approach is that we often release code which has some bugs. Sometimes these manifest as 404 and 50* errors.
I was hoping to use our F5 iRule to log these errors, so that it will help with our debugging.
Based on this http://devcentral.f5.com/wiki/default.aspx/iRules/LogHttpHeaders.html, I am thinking of doing:
when RULE_INIT {
Debug off (0), Debug on (1)
set ::debug 1
}
when HTTP_REQUEST {
set RequestLogString "(Client) [IP::client_addr]:[TCP::client_port] (Url) [HTTP::host][HTTP::uri]"
Our existing routing logic
...
}
when HTTP_RESPONSE {
if { $::debug > 0 } {
if { [HTTP::status] == 404 || [HTTP::status] > 499 } {
log local0. "$RequestLogString (responsestatus) [HTTP::status]"
foreach aHeader [HTTP::header names] {
if { $aHeader contains "OurCustomHeader" } {
log local0. "$RequestLogString (responsestatus) [HTTP::status] $aHeader [HTTP::header value $aHeader]"
}
}
}
}
}
A few questions:
1. Assuming we have heavy traffic, should I be concerned about the number of times the HTTP_RESPONSE event fires and the check for debug flag and status is done, in terms of performance. Currently the F5 is not loaded (an average of 25% of the CPU is used during peak hours).
2. We are not quite sure as of now how many 404s and 50* will turn up when I turn this rule on. Is it possible the logging will effect F5 performance in case we have a lot of these?
3. When I set the RequestLogString for each request, but not use it for good http responses, will this variable be cleaned up or collected after the response is done i.e. could there be possible side effects to just setting this variable and letting it be cleaned up at whatever time the iRule engine(?) does it.
4. I was thinking of adding [IP::server_addr] in the RequestLogString, to get the internal server where the request was destined, this help us a lot with our debugging. However on the test environment F5, at one time I got:
TCL error: TestRule HTTP_REQUEST - Error: No serverside connection established line 1 invoked from within IP::server_addr
Maybe this was just because I did something wrong at that time. Should i just not use [IP::server_addr] in the logging rule?
Thanks,
Sriram
hooleylistCirrostratus
Hi Sriram,
That looks about as efficient as it could be with one exception: I'd try to avoid looping through every header name in HTTP_RESPONSE unless you have to and don't know the full header name you want to log. If you do know the name, you can just use HTTP::header value "OurCustomHeader".
Also, a pool member hasn't been selected by the time HTTP_REQUEST is triggered and a serverside connection hasn't been established. So IP::server_addr won't work. You could log the server IP in HTTP_RESPONSE though using IP::server_addr.
Aaron- hooleylistSorry, one other possible big optimization:
If you're on a CMP capable platform, remove the global variable for debug. For 10.x, you can use static::debug instead. For 9.x, you can use a local variable in HTTP_REQUEST (set debug 1 for example).
Aaron 
sriramgd_111845Thanks Aaron. This gives me more confidence to deploy the rule in production tonight during downtime. I will make the changes you suggested, before deploying.
Will keep the old rule without the response event on hand in case operations reports any problems in the morning.
Will post here on how it goes.- sriramgd_111845Thanks Aaron. This gives me more confidence to deploy the rule in production tonight during downtime. I will make the changes you suggested, before deploying.
Will keep the old rule without the response event on hand in case operations reports any problems in the morning.
Will post here on how it goes. - sriramgd_111845I turned this rule while only checking for 50* errors. Works well, I can see the occassional 50* errors being logged. Compared to the good traffic this is a minuscule amount. There is no effect on the performance in the graphs or with top command.
The thing is the technique works well. We will consider turning it on for short durations to get an idea of the 404s too. And possibly use it for debugging in future releases.
Thanks Aaron!