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

From: "Rainer Gerhards" <[email-masked]>
Date: Wed, 3 Feb 2010 17:34:47 +0100

Hi all,

I just subscribed to the sip-clf mailing list. I am the author of rsyslog,
one of the major open source syslogd's as well as the designer for a number
of Windows tools that are syslog-based. I have also worked on the IETF syslog
standardization effort.

David has made me aware of the current discussion and I am currently working
through the mailing list. Two things that I would like to comment on are
transmission of Apache logs via syslog and syslog performance.

As of my experience, it is quite common to transport Apache clf "files" via
syslog. There are two was to do this: one is to make apache log in real-time
to the syslogd, usually with the help of logger or a similar system tool.
This requires proper engineering and can potentially cause notable
performance degradation. As I know from the rsyslog user base, these problems
can be solved and this mode is used in practice, even for high-performance
sites.

The other approach is to let apache write to text files and then transfer
these text files in near-realtime to a syslogd. That is, a process grabs data
as it is appended to the text log. In rsyslog, the omfile module has
specifically been written for that use case and, if I remember correctly, the
root cause for its implementation was Apache clf transfer.

It may also be worth noting that in the Apache scenario log4j syslog logging
seems to come together with clf - but I don't have insight if this is true
for the majority of cases. 

On syslog performance: I have read that expected message volume was
considered problematic for the syslog use case. It may be worth noting that
high-volume sites log data via syslog. This may be clf, but the larger ISP or
financial institutions (or other service providers) already have lots of log
data that is to be processed. For rsyslog, I know of deployments that average
50,000+ messages per second on a single receiving machine. In lab setup, a
single instance of rsyslog can currently process up to 250,000 msgs per
second, with this rates going up. The Windows products I am responsible for
reach similar or higher message rates. Of course, these number depend much on
the length of the message, parsing overhead and what the final destination
does with the messages (it is a big difference writing them to a flat ascii
file or a database and complex filtering also reduces the throughput). Note
that there is large demand for even faster syslog implementations, which
leads me to believe that transmission of mass data via syslog is often
desired.

I am not sure what message rates are expected for sip and where the actual
problem for syslog was envisioned. If you have some more information on that,
it would definitely help me understand the situation at large.

Rainer Gerhards

---

From: "Spencer Dawkins" <[email-masked]>
Date: Wed, 3 Feb 2010 10:49:44 -0600

Rainer,

<as-co-chair>

Welcome, and thanks for subscribing!

</as-co-chair>

<as-participant>

Your note is very interesting to me - I just fired off a question to Dave 
on-list that might also be helpful for you to think about. I'd appreciate 
any thoughts you can provide!

</as-participant>

Thanks,

Spencer

> _______________________________________________
> sip-clf mailing list
> [email-masked]
> https://www.ietf.org/mailman/listinfo/sip-clf

---

From: "Vijay K. Gurbani" <[email-masked]>
Date: Wed, 03 Feb 2010 17:44:38 -0600

Rainer Gerhards wrote:
 > I just subscribed to the sip-clf mailing list. I am the author of
 > rsyslog, one of the major open source syslogd's as well as the
 > designer for a number of Windows tools that are syslog-based. I have
 > also worked on the IETF syslog standardization effort.

Rainer, David: Thanks for the information on syslog.  Let me
state for the record that I do like syslog, having used it a lot
in the past ;-)

 > I am not sure what message rates are expected for sip and where the
 > actual problem for syslog was envisioned. If you have some more
 > information on that, it would definitely help me understand the
 > situation at large.

Regarding what message rates are expected for SIP, it is hard
to give an authoritative answer.  However, early work on SIP
performance [1] and more recent work on SIP overload control
[2,3,4] appear to indicate that steady state is obtained
around 200-300 calls per second under certain assumptions.
That said, there may be experimental SIP systems that run on
powerful hardware with all kinds of optimizations turned on and
more simplifying assumptions to give you a higher call rate
in steady state than the published literature.  In other words,
YMMV.

For the sake of argument, let's assume 1,000 calls per second
to be the high watermark and 300 calls per second to be the low
watermark in steady state.

Since a call in SIP is composed of many messages, let's analyze
the number of messages exchanged to set up a call.  Using some
simplifying assumptions such as the SIP server (a proxy)
does not Record-Route and that at most we fork to two
downstream user agents, a simple call consists of 8 messages
(see Figure 1) and a more complex call that involves forking
contains at least 16 messages (Figure 2; forking in SIP
implies amplification of the original request to one or
more down-stream endpoints, and dealing with the resulting
responses, etc.  Note that you can end up with more than 16
messages if multiple provisional responses are received or if
re-transmission of certain messages occur.  But for the sake of
simplicity, let's stick with 16 messages.)

   SIP server                         SIP server
   producing CLF                      producing CLF
INV    |                            INV    |
------>|                            ------>|
100    |INV                         100    |
<------|------>                     <------|INV
        |100                                |------>
        |<------                            |100
        |180                                |<------
        |<------                            |INV
    180 |                                   |------->
<------|                                   |100
        |200                                |<------
        |<------                            |
    200 |                                   |180
<------|                                   |<------
                                     180    |
Figure 1: Simple SIP call           <------|180
                                     180    |<------
                                     <------|
                                            |200 OK INV
                                            |<------
                                 200 OK INV |
                                     <------|
                                            |CANCEL
                                            |------>
                                            |200 OK CANCEL
                                            |<------
                                            |487 INV
                                            |<------
                                            |ACK
                                            |------>
                                     Figure 2: Complex SIP call

Each message here will generate a CLF record.  In steady
state, a server generating SIP CLF records will thus generate
at least 2,400 records per second and at most 16,000 records
per second with the simplifying assumptions I stated (i.e.,
no Record-Route and only fork to two endpoints.)  If the SIP server
Record-Routed or forked to more than two endpoints, the
message load will increase (on the average, to each endpoint
it forked, it will have to handle 6-7 extra messages if we
consider that n-1 endpoints will have a CANCEL generated
towards them.  So three forked endpoints will require the
SIP server to generate about 23,000 CLF records per second.)

Given your data on rsyslog of 50,000+ messages per second on
a single receiving machine, it seems that for rsyslog daemon,
these messages do not pose a problem since it is designed
to handle messages from many applications and hosts.

But is sending 23,000 messages per second a good use of
syslog for an application?  Especially because in your
email you also noted that:

 > As of my experience, it is quite common to transport Apache clf
 > "files" via syslog. There are two was to do this: one is to make
 > apache log in real-time to the syslogd, usually with the help of
 > logger or a similar system tool. This requires proper engineering and
 > can potentially cause notable performance degradation. As I know from
 > the rsyslog user base, these problems can be solved and this mode is
 > used in practice, even for high-performance sites.

I am afraid of forcing SIP vendors to transport SIP CLF via
syslog will just mean that they will choose not to do it if it
will cause notable performance degradations.

 > The other approach is to let apache write to text files and then
 > transfer these text files in near-realtime to a syslogd. That is, a
 > process grabs data as it is appended to the text log. In rsyslog, the
 > omfile module has specifically been written for that use case and, if
 > I remember correctly, the root cause for its implementation was
 > Apache clf transfer.

The above approach is something that is attractive more because
of the fact that -- correct me if I am wrong -- syslog records
have to be ASCII, right?  If so, then one of the requirements
we have been working with is that these records should be
amenable to fast searches (hence the indexed-ASCII [5] approach that
is being discussed as a possible candidate for SIP CLF).  So,
if we go the syslog route, then these records would have to be
changed from ASCII to some indexed representation for faster
searches somewhere after they have been processed by the syslog
daemon.

Alternatively, one could generate SIP CLF using indexed-ASCII
format and have loggers read it and inject syslog records but
only for the most important ones (instead for *all* SIP messages.)
I find the above option more attractive since the implementation
overhead for a specific SIP server is less -- just write the
CLF to a disk file.

And finally, since SIP runs on all kinds of devices and environments,
do you know how pervasive the syslog library is?  Would a developer
find it in BREW operating environment or Android?  You noted log4j
in your email as well, and some Googling seems to show that
Android supports log4j more than syslog (but I could be wrong.)
In any case one of the attractive reasons to stay with disk-based
CLF is precisely that it allows an SIP server to only depend on the
file I/O primitives, which are guaranteed to be provided on all
platforms.

[1] Gurbani, V.K., Jagadeesan, L.J., and Mendiratta, V.,
  "Characterizing Session Initiation Protocol (SIP) Network
  Performance and Reliability," Springer Verlag Lecture Notes
  in Computer Science (LNCS), Vol. 3694, pp. 196-211, October 2005.
[2] Hilt, V. and I. Widjaja, "Controlling Overload in Networks of
  SIP Servers", IEEE International Conference on Network Protocols
  (ICNP'08), Orlando, Florida, October 2008.
[3] Noel, E. and C. Johnson, "Initial Simulation Results That
  Analyze SIP Based VoIP Networks Under Overload",
  International Teletraffic Congress (ITC'07), Ottawa, Canada,
  June 2007.
[4] Shen, C., Schulzrinne, H., and E. Nahum, "Session Initiation
  Protocol (SIP) Server Overload Control: Design and Evaluation,
  Principles", Systems and Applications of IP Telecommunications
  (IPTComm'08), Heidelberg, Germany, July 2008.
[5] Roach, A., "Binary Syntax for SIP Common Log Format",
  IETF Internet-Draft, work in progress, 2009
  http://tools.ietf.org/html/draft-roach-sipping-clf-syntax-01

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/

---

From: "Rainer Gerhards" <[email-masked]>
Date: Thu, 4 Feb 2010 14:58:42 +0100

Hi Vijay,

> -----Original Message-----
> From: Vijay K. Gurbani [mailto:[email-masked]]
> Sent: Thursday, February 04, 2010 12:45 AM
> To: Rainer Gerhards; David Harrington
> Cc: [email-masked]
> Subject: Re: [sip-clf] A syslog approach to sip logging
> 
> Rainer Gerhards wrote:

Thanks for noting that ;) But I understand that there is not a certain bias
against syslog in this WG. The syslog community obviously did not do a good
enough task in making syslog use cases universally visible.

What matters is finding a sound technical solution, and I hope that my
comments help doing that. While my view is unquestionable "syslogish", I try
to spell out what syslog can do - and what it cannot do, or at least where I
see problem areas.

>    producing CLF                      producing CLF

Thanks for the good information. I did some math:

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.

So for case 1, we have 250,000KB per second, so roughly 250MB per second.
That means that we need to have 2GB transport capacity if no compression
takes place. For case 2, we have 25MB/200MBit per second.

IETF syslog currently does NOT support compression. So syslog requires quite
some bandwidth to transfer that amount of data. Note that some of the leading
syslog implementation support zip compression. In rsyslog, this can lead to
considerable reduction in the data transfer rate, but obviously at some
computing cost. There is no current IETF effort to standardize compression.

As a side-note, the above numbers (in case 1) mean that a 1TB-Drive will fill
up with a text file sip log in roughly an hour.

> will cause notable performance degradations.

The problem is that Apache does not include a native syslog forwarding
capability. I am not an Apache expert, but what I learned from my user base
is that there are different ways to make Apache talk to a third-party process
for logging. Some of these methods seem to involve per-request process
creation, others not. Obviously, the per-request process creation causes
problems. However, using the right method, these problems do not exist. I
don't have the details of which method is right and which is not (but I could
dig them out), but the key problem is that Apache seems to lack native syslog
support for the logs.

As a side-note, I fully agree to your view of not forcing someone to do
things which may smell bad to them. We tried this in syslog with rfc3195,
which is a great RFC, but so far away from traditional syslog that nobody
(but poor me...) ever implemented it. We had lots of discussions in the
syslog wg where I objected some very good things simply for the reason that
we would break momentum (and others objected some things I would really liked
to have seen). The end result seems like we did the right thing: the new set
of standards is already supported by major implementations.

> have to be ASCII, right?  

I've been more precise in previous postings (this morning), but let's say
that syslog logs must contain valid UTF-8 sequences.

> If so, then one of the requirements
> is being discussed as a possible candidate for SIP CLF).

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) "

"text file" usually comes with the co-notation of printable ASCII that can be
processed with an editor or tools like grep. That was what I assumed when I
read the problem statement. I think this is not compatible with [5], and
probably a reason why [5] says it is a counter-proposal ;)

>  So,

you are assuming now that the problem statement gets changed, right?

> Android supports log4j more than syslog (but I could be wrong.)

But log4j has a syslog transport provider, so whoever logs to log4j, can also
log to syslog - it's just a matter of log4j configuration.

> file I/O primitives, which are guaranteed to be provided on all

Forgive me if I come up with something that was already considered by the WG
in the past. In my limited understanding, it sounds like the most important
thing to create is the "information model" (or semantic object base). That is
a description of

a) which properties exist
b) which syntax do they have
c) which log record types exist
d) which log record type can contain which properties

To me, this sounds like an isolated RFC. That would be a document that talks
about the application-level view, but not about any non-app-level syntaxes
and semantics (and specifically NOT about representation in a file). Such a
document would be very valuable, serving as a dictionary where all log types
and the relationships between them would be precisely defined. I wish we had
something like this for important syslog use cases. The real trouble with
syslog is understanding what an event means, because there is no such
dictionary.

Once it is clear from the app perspective what a sip log record is, it is
easy to create mappings to underlying "transports". For example, there could
be mappings that describe how to encode sip log entries for

1) ascii text files
2) the format specified in [5]
3) syslog transmission

These mappings should be trivial to create. But the real beauty of such an
approach would be that it would also be easy to create mappings from 1 to 3,
2 to 3 and so on. Inside a sip application, these mappings could be driver
layers, so that an operator, based on his or her requirements, selects the
one that best fits. That would, among others, enable the very same sip
application to be used in an environment where it reports directly to syslog
or alternatively log to a ascii text file. In the later case, a system
process could then come along, parse the text file, convert it to syslog,
transmit it via syslog and the syslogd could write it out as a text file
again (or in the format describe in 5, provided that such functionality is
present in the syslogd [thinking rsyslog plugin here]).

Also, one could convert text files to [5], and vice versa, via the
well-defined specifications.

In my experience, finding agreement on the application-level objects among
different vendors is the really hard task. So, with my limited understanding
of the sip industry, I would suggest to focus on that task, and leave all the
"transport" details out of that discussion. I am sure they can be solved with
ease either in parallel or after the information model has been defined. The
plus is that you do not need to care about transport problems at all, because
there already exist a variety of transports (including things like scp and
rsync!) that can be used.

IMHO the only thing that needs to be considered inside the information model
is the fact that sip log records need to be correlated among different
systems. So I think there should be some capability inside the information
model that can be used to consolidate entries from different systems (and
syslog experience tells that a timestamp alone, even with high-precision, is
not sufficient to solve that task).

Rainer

---

From: "Vijay K. Gurbani" <[email-masked]>
Date: Fri, 12 Feb 2010 15:27:55 -0600

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

 > 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.

 > "This document proposes a binary syntax for the SIP common log

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