Forum Discussion

kiwibloke_17342's avatar
kiwibloke_17342
Icon for Nimbostratus rankNimbostratus
Mar 27, 2012

HSL logging sending multiple log entries in one message?

Hi,

 

 

I have an iRule that generates Apache style "combined" format access logs for one of our sites. it is based on the iRule for "W3c logging".

 

 

Our LTMs run 10.x so HSL is an option. These logs are destined to be used for fraud detection systems, so I have to use TCP.

 

 

I have one syslog server in the syslog pool and it should be able to handle the traffic.

 

 

The irule is attached as is an example (sanitised) access log captured on the syslog server.

 

 

The syslog server takes the entire message received and dumps it raw as a single log entry into a log file that rolls hourly.

 

 

Most of the time it seems to be that one request = one log entry, however occasionally I see a single log entry as being made up of two distinct http_requests

 

 

Its almost as if the events have been concatenated together before being sent. logic tells me this can't happen since the iRule only fires once per request, so by virtue of that alone one request should equal one log entry.

 

 

Has anyone else come across this before? I want to rule out the LTMs before I look deeper at the syslog server.

 

 

KB

 

 

application delivery
dev
devops
iRules

8 Replies

Sort By
  • hooleylist's avatar
    hooleylist
    Icon for Cirrostratus rankCirrostratus
    Mar 27, 2012
    Hi KB,

     

     

    I think by design, HSL can reuse an existing connection to the pool for multiple messages. Ideally, the syslog server would be able to split the messages regardless of the connection reuse. Or maybe you could configure the syslog server to close the connection after one message? I'm not sure there is a simple way to prevent connection reuse on HSL.

     

     

    Aaron
  • kiwibloke_17342's avatar
    kiwibloke_17342
    Icon for Nimbostratus rankNimbostratus
    Mar 27, 2012
    Hi,

     

     

    Thanks, I am going to run TCP dump shortly so I can do a packet analysis to see exactly what the LTMs are firing out.

     

     

    It still seems odd that I am seeing multiple messages appearing in a single message transmit only some of the time. I would expect it that would be doing this all the time or none of the time. it can't be load related as I am using a shadow vIP for my testing. I am the only one hitting the shadow vIP and I am pretty sure F5 designed the HSL engine to scale higher than one concurrent user! :D

     

     

    Regarding the site this is intended for the page I am testing on generates 25 http requests, yet I usually only see 20 lines in the log

     

     

    Thanks for your help, if i find out anything that might be useful to the group I will post my findings.

     

     

    Cheers,

     

     

    KB
  • kiwibloke_17342's avatar
    kiwibloke_17342
    Icon for Nimbostratus rankNimbostratus
    Mar 27, 2012
    Done the TCP dump.

     

     

    It looks as if the LTM is sending multiple log entries in some of its transmissions

     

     

    I have seen some packets that contain upto 3 access log entries.

     

     

    I wonder if this is a direct consequence of using TCP over UDP.

     

     

    If using UDP it wouldn't have the overhead of a handshake on every packet so it probably just fires them out individually. Using TCP it does so it might be optimizing each sent packet to contain as much information a possible so as to reduce the overhead of the handshake.

     

     

    I think I need to log a support ticket.

     

     

    :)
  • hooleylist's avatar
    hooleylist
    Icon for Cirrostratus rankCirrostratus
    Mar 28, 2012
    If you do open a case with F5 Support, can you post the case number so I can follow it?

     

     

    Thanks, Aaron
  • Jessie_O__45052's avatar
    Jessie_O__45052
    Historic F5 Account
    Mar 28, 2012
    Classical syslog (RFC3164) expects one message per UDP packet with no terminating newline. Many servers also support TCP transport and expect the messages to be separated by newlines, but there is no formal standard for this -- even the later RFC5424 does not define how messages should be separated when encapsulated in protocols other than UDP.

     

    Your iRule is not providing a separator, so message separation is essentially being left up to server intelligence and luck. If you add a "\n" to the end of your string, your problems should go away :).

     

    It would be possible to make HSL::send "smart" enough to automagically append a newline when logging to a TCP destination and add a -nonewline flag for users who really do want a "raw" send so they can use arbitrary separators. OTOH, any time you make something "smart", you also make it more confusing.

     

  • kiwibloke_17342's avatar
    kiwibloke_17342
    Icon for Nimbostratus rankNimbostratus
    Mar 28, 2012
    Hi,

     

     

    The case ID is C1087278.

     

     

    Thanks for the tip Jessie, I thought about this last night too!

     

     

    So this morning I added a "\r\n" to the end of the log entry (a CRLF) and configured my syslog server to split on CR/LF.

     

     

    Hey presto it works.

     

     

    I also had to do some tweaking on the clock format and handling for when referrer,content size and uri_query were zero. But that was pretty straight forward.

     

     

    So now the iRule output looks identical to the output you'd get from an Apache tomcat server using the combined log format.

     

     

    KB.
  • kiwibloke_17342's avatar
    kiwibloke_17342
    Icon for Nimbostratus rankNimbostratus
    Mar 28, 2012
    The final (sanitised) iRule is attached.

     

     

    This iRule generates Tomcat "combined" format style access logs and sends them via HSL to your remote syslog server.

     

     

    KB.

     

  • hooleylist's avatar
    hooleylist
    Icon for Cirrostratus rankCirrostratus
    Mar 28, 2012
    Nice work kiwi. And thanks for the info Jessie. I need to go back and add terminators to all my HSL examples now!

     

     

    Aaron