Re: [sip-clf] A syslog approach to sip logging

"Vijay K. Gurbani" <vkg@alcatel-lucent.com> Fri, 12 February 2010 21:27 UTC

Return-Path: <vkg@alcatel-lucent.com>
X-Original-To: sip-clf@core3.amsl.com
Delivered-To: sip-clf@core3.amsl.com
Received: from localhost (localhost [127.0.0.1]) by core3.amsl.com (Postfix) with ESMTP id 294343A790C for <sip-clf@core3.amsl.com>; Fri, 12 Feb 2010 13:27:10 -0800 (PST)
X-Virus-Scanned: amavisd-new at amsl.com
X-Spam-Flag: NO
X-Spam-Score: -2.23
X-Spam-Level:
X-Spam-Status: No, score=-2.23 tagged_above=-999 required=5 tests=[AWL=-0.231, BAYES_00=-2.599, J_CHICKENPOX_24=0.6]
Received: from mail.ietf.org ([64.170.98.32]) by localhost (core3.amsl.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id OdSn9NWK9QmJ for <sip-clf@core3.amsl.com>; Fri, 12 Feb 2010 13:27:08 -0800 (PST)
Received: from ihemail3.lucent.com (ihemail3.lucent.com [135.245.0.37]) by core3.amsl.com (Postfix) with ESMTP id A924C3A790B for <sip-clf@ietf.org>; Fri, 12 Feb 2010 13:27:08 -0800 (PST)
Received: from umail.lucent.com (h135-3-40-63.lucent.com [135.3.40.63]) by ihemail3.lucent.com (8.13.8/IER-o) with ESMTP id o1CLRunG006460 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO); Fri, 12 Feb 2010 15:27:56 -0600 (CST)
Received: from [135.185.236.17] (il0015vkg1.ih.lucent.com [135.185.236.17]) by umail.lucent.com (8.13.8/TPES) with ESMTP id o1CLRtIc014743; Fri, 12 Feb 2010 15:27:56 -0600 (CST)
Message-ID: <4B75C7DB.2030909@alcatel-lucent.com>
Date: Fri, 12 Feb 2010 15:27:55 -0600
From: "Vijay K. Gurbani" <vkg@alcatel-lucent.com>
Organization: Bell Labs Security Technology Research Group
User-Agent: Thunderbird 2.0.0.6 (Windows/20070728)
MIME-Version: 1.0
To: Rainer Gerhards <rgerhards@hq.adiscon.com>
References: <9B6E2A8877C38245BFB15CC491A11DA71037F7@GRFEXC.intern.adiscon.com> <4B6A0A66.1050405@alcatel-lucent.com> <9B6E2A8877C38245BFB15CC491A11DA710380E@GRFEXC.intern.adiscon.com>
In-Reply-To: <9B6E2A8877C38245BFB15CC491A11DA710380E@GRFEXC.intern.adiscon.com>
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit
X-Scanned-By: MIMEDefang 2.57 on 135.245.2.37
Cc: sip-clf@ietf.org
Subject: Re: [sip-clf] A syslog approach to sip logging
X-BeenThere: sip-clf@ietf.org
X-Mailman-Version: 2.1.9
Precedence: list
List-Id: SIP Common Log File format discussion list <sip-clf.ietf.org>
List-Unsubscribe: <https://www.ietf.org/mailman/listinfo/sip-clf>, <mailto:sip-clf-request@ietf.org?subject=unsubscribe>
List-Archive: <http://www.ietf.org/mail-archive/web/sip-clf>
List-Post: <mailto:sip-clf@ietf.org>
List-Help: <mailto:sip-clf-request@ietf.org?subject=help>
List-Subscribe: <https://www.ietf.org/mailman/listinfo/sip-clf>, <mailto:sip-clf-request@ietf.org?subject=subscribe>
X-List-Received-Date: Fri, 12 Feb 2010 21:27:10 -0000

Because some time has passed since the last email exchange in this
thread, here are the links to my posting and Rainer's response.

My posting:
  http://www.ietf.org/mail-archive/web/sip-clf/current/msg00123.html

Rainer's response:
  http://www.ietf.org/mail-archive/web/sip-clf/current/msg00133.html

That said, Rainer Gerhards wrote:
 > Thanks for the good information. I did some math:

Rainer: Thanks for digesting all the SIP protocol details.
More inline.

 > Let me assume 25,000 log messages per second. Some post stressed the
 > fact that sip clf seems to be very lengthy. So let me assume for case
 > 1 that a message is 10k in size and for case 2 that a message is
 > 1k in size.

I presume by "case 1" and "case 2" you meant Figures 1 and 2,
respectively.  If so, the message size will not vary too much
between Figures 1 and 2 (to be sure, it varies a bit as headers
are added and removed when a SIP request is proxied between
more than one domain, but not by that much to cause a 10k
message to shrink to a 1k one.)

Trying to establish an average SIP message size is also fraught
with peril.  Because SIP can be used in direct peer-to-peer
communications as well as session setup by a managed network,
the message size can oscillate from a few hundred bytes for the
former case to thousands of bytes for the latter.  Furthermore,
since SIP has the capacity to initiate sessions as well as do
much more, the exact payload being carried in the SIP message
has a bearing on the message size.

That said, let's see if we can derive some lower bound to a set
of canonical SIP fields that will go into the CLF.  Let's assume
that the SIP CLF is /not/ storing the entire message, but just
those fields that would constitute the mandatory fields of a soon-
to-be defined data model.  By my calculation [2], a CLF record of
the mandatory data fields will consist of 524 bytes.  For the
sake of argument, even though we can compress the response CLF
record since it contains some repeated information from the
request CLF record, let's just assume that they are equivalent
in size.  Thus, given an arrival rate of 25,000 log messages per
second, we have about 13 MBytes/s (or ~105 Mbits/s) of CLF data
being generated.  This starts to present some challenges to a
100 Mbits/s CSMA/CD local area network in terms of collisions.
Now, note that this is what will constitute a bare minimum CLF
record; if other fields are logged, or the entire SIP message,
then this number grows rather rapidly.

With this in mind, it may help to do some high-level cost analysis
of using syslog (I am not claiming that the cost-analysis below
is authoritative or sacrosanct, rather that let's use this as a
starting point for discussions.  If I make a mistake somewhere,
as I am sure I have, please do point it out.)

Now I realize that syslog can log into a disk file, but if we do
that then we may as well log CLF records directly to a disk file.
So let's assume that the usage of syslog includes transporting the
message either through the Unix local domain socket to a local
syslog daemon or through an Internet socket to a remote syslog daemon.

The evaluation of syslog, then, is subject to the following
constraints:

(a) The arrival rate of messages at a syslog daemon;
(b) The volume of data transferred;
(c) Whether syslog is used to log exceptional messages or to log
any (and all) messages from a SIP server;
(d) Whether syslog is available on all platforms that a SIP
entity can be hosted.

Regarding (a), I suspect we can lay that down to rest as per
your email of Feb 3, 2010 [1].  In that you mention rates of
50,000+ messages per second on a single receiving machine.  Assuming
that the syslog daemon is simply logging these to a disk file
(/var/log/messages), it seems that 25,000 messages should be
easy to handle.

(b) is a bit more complex.  The volume of data to be transferred
from a SIP CLF producing entity to the syslog daemon is about
105 Mbits/s in the most optimistic of scenarios.  Clearly,
this does not pose a problem when CLF is being appended to a local
file.  On the other hand, I am not sure if we can effectively
send 105 Mbits/s to a remote syslog server, or even a local
syslog daemon.  It seems to me that if we were to write as many
524 byte records in 1 second to syslog versus a local file,
the effective throughput will be higher for the local file in
terms of number of records written.

I also realize that there are programmatic techniques to mitigate
the effect of slow network I/O (buffering, etc.)  However, it is
also true that developers follow the path of least resistance.
If we force SIP vendors to implement some buffering or threading,
etc. so that transmitting the CLF data in real-time does not end
up slowing down the rest of the server, I am sure that this will
simply slow down the adoption rate of SIPCLF.

Regarding (c), I always thought that syslog should only be used
to log critical messages, not the normal machinations occurring
at a SIP server (and indeed Apache's canonical use of syslog
seems to validate this approach where they use syslog for error
messages, but normal disk-based files for CLF).  But from your
previous posts, it appears that people are indeed using syslog
as a logging tool.

Regarding (d), it seems that syslog libraries may be ubiquitous,
but there will be isolated pockets of SIP equipment running on
networks where it is not possible to converse with the nearest
syslog daemon (consider a SIP user agent on a smart phone that
wants to keep a log of calls but does not -- or cannot -- contact
its home syslog daemon in an expedient manner.)

(a), (c) and (d) seem to support the use of syslog, but intuitively
it appears that (b) detracts from it.  Any feedback on this will
be very helpful.

 > Mhhh... aren't the problem statement and [5] contradictory?
 > The problem statement says in section 4
 > "The SIP CLF is a standardized manner of producing a text file."
 > While [5], right in the abstract, says:
 > "This document proposes a binary syntax for the SIP common log
 > format (CLF) "

The format in [5]
(http://tools.ietf.org/html/draft-roach-sipping-clf-syntax-01) is
not strictly binary, more along the line of indexed-ASCII that
can still processed with Unix text processing tools.

I am updating draft-ietf-sipclf-problem-statement to include a
data model, and perhaps an information model as well.  Hopefully,
the discussion we are having here goes towards helping flesh out
these models.

[1] http://www.ietf.org/mail-archive/web/sip-clf/current/msg00113.html
[2] Method, 10 bytes; Date 16 bytes; CSeq number, 10 bytes; Server
  transaction, 80 bytes; Client transaction, 80 bytes; To header
  including tag, 80 bytes; From header including tags, 80 bytes;
  R-URI including parameters, 80 bytes; Call-ID, 80 bytes; sender
  IP:port, 18 bytes.

Thanks,

- vijay
-- 
Vijay K. Gurbani, Bell Laboratories, Alcatel-Lucent
1960 Lucent Lane, Rm. 9C-533, Naperville, Illinois 60566 (USA)
Email: vkg@{alcatel-lucent.com,bell-labs.com,acm.org}
Web:   http://ect.bell-labs.com/who/vkg/