Hi Vijay,

> -----Original Message-----
> From: Vijay K. Gurbani [mailto:vkg@alcatel-lucent.com]
> Sent: Thursday, February 04, 2010 12:45 AM
> To: Rainer Gerhards; David Harrington
> Cc: sip-clf@ietf.org
> Subject: Re: [sip-clf] A syslog approach to sip logging
> 
> 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 ;-)

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.

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

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.

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

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

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

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

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

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

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.

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

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
> 
> [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/