Forum Discussion

Deb_Allen_18's avatar
Deb_Allen_18
Historic F5 Account
May 05, 2006

Missing log entries

I'm testing whether redirect with Keepalive header is really kept alive, so I wrote this little rule to try to keep the connection alive long enough for me to see it in netstat and then see when it goes away:

when HTTP_REQUEST {
  HTTP::header remove Connection
  for {set x 0}{$x<10000}{incr x}{
    log local0. $x
  }
  HTTP::redirect http://www.google.com/
}

What I'm seeing is a bit odd: It logs up to x=220, then /sometimes/ resumes logging again somewhere in the 900's, but never logs between 221 and 900, and only once did I see it log up to 999 as expected (still with the gap after 220).

I'm not seeing any errors or syslog message compression (no "last message repeated..." in logs)

Of course, this isn't a real world scenario, but it concerns me that the logging is just stopping. Lots of my customers are using logging to alert them to rule exceptions, and it would be good to know whether this is a reliable facility, or if the execution speed of the loop is just overwhelming the log facility. (seems odd that it so consistently bites it after iteration 221...)

thanks!

/deb

application delivery
dev
devops
iRules
  • JRahm's avatar
    JRahm
    Icon for Admin rankAdmin
    May 16, 2006
    I tested your rule on my 9.1.1 6400, I got:

     

     

     

    [root@ccp-b3f2labslb-1:Active] config tail -f /var/log/ltm

     

    May 16 08:28:21 tmm tmm[32695]: 01220002:6: Rule test : Number 0

     

    May 16 08:28:21 tmm tmm[32695]: 01220002:6: Rule test : Number 1

     

    May 16 08:28:21 tmm tmm[32695]: 01220002:6: Rule test : Number 2

     

    May 16 08:28:21 tmm tmm[32695]: 01220002:6: Rule test : Number 3

     

    May 16 08:28:21 tmm tmm[32695]: 01220002:6: Rule test : Number 4

     

    May 16 08:28:23 tmm tmm[32695]: 01220002: repeated 995 times

     

  • Deb_Allen_18's avatar
    Deb_Allen_18
    Historic F5 Account
    May 16, 2006
    hmmm...

     

    thanks for testing, citizen elah.

     

    (I was testing on 9.2.3)

     

     

    In your case, the loop at least executed the of times expected, and hit the syslog each time.

     

     

    Are you logging to local0., or the default facility? (I seldom see logline compression unless logging to the default facility.)

     

     

    I'm planning to test further with some longer-duration actions inside the loop to determine if we're just overloading syslog, so I guess I'll test with different facilities as well.

     

     

    thanks again for the additional info!

     

    /deb
  • JRahm's avatar
    JRahm
    Icon for Admin rankAdmin
    May 16, 2006
    Your assumption is correct, I was logging to the default facility. When I changed it to local0, I got similar but not identical behavior. I tried several different facilities and levels, and the results are the same. If I put a timing loop in front of the log statement, I get all my log statements. I found that variable Y must increase as the limit for variable X is increased. For example, I consistently get all 300 lines if I have a 12 count loop in between each log statement

    
  for {set x 0}{$x<300}{incr x}{
    for {set y 0}{$y<12}{incr y} { }
    log local0 "Number $x"
  }

    But if I need 1000 of them, the delay loop needs to be much longer:

    
  for {set x 0}{$x<1000}{incr x}{
    for {set y 0}{$y<100}{incr y} { }
    log local0. "Number $x"
  }

    It appears to me that syslog is getting overloaded.