Subject: [dispatch] SIP-CLF: Extensibility considerations (was Results on ASCII vs. binary representation)

From: Adam Roach <[email-masked]>
Date: Thu, 30 Apr 2009 15:08:06 -0500

Vijay K. Gurbani wrote:
> Hadriel Kaplan wrote:

>> But anyway, I think the real question that needs to be answered
>> *first* is "what is the purpose of the CLF?" What is it going to
>> help admins do? Is it for troubleshooting, or for registration audit
>> logging, or for IDS systems, etc?
>
>  From the list above, at least for troubleshooting, logging, and
> IDS systems. What I do not envision CLF being used for is
> debugging (distinct from troubleshooting) and CDR.

Even knowing the list of purposes, if we go with a text format similar 
to what is proposed, we are going to be forced to nail down the complete 
set of log record fields now, with little hope for backwards-compatible 
extensibility in the future. Admittedly, we *could* go to a tagged text 
format (e.g. where the fields are explicitly labeled instead of being 
inferred by position) to address this shortcoming, but that's not what's 
being proposed at the moment.

So, if we go down the path proposed in draft-gurbani-..., we're strapped 
with coming up with the perfect set of future-proof fields that 
encompasses everything anyone will ever need in the log file, while (at 
the same time) not including extraneous information that people don't 
want to bother generating and/or parsing.

The binary format I've proposed allows for exclusion of information the 
logging node doesn't consider relevant, as well as inclusion of 
information that we don't define at this time. For me, that's almost as 
big a win as the efficiency in searching a file for records of interest.

/a

---

From: "Vijay K. Gurbani" <[email-masked]>
Date: Thu, 30 Apr 2009 16:12:14 -0500

Adam Roach wrote:
> Even knowing the list of purposes, if we go with a text format
> similar to what is proposed, we are going to be forced to nail down
> the complete set of log record fields now, with little hope for
> backwards-compatible extensibility in the future. Admittedly, we
> *could* go to a tagged text format (e.g. where the fields are
> explicitly labeled instead of being inferred by position) to address
> this shortcoming, but that's not what's being proposed at the moment.

The tagged format will add further latency to an ASCII format,
so I did not include it.  In the best case, I am looking for an
ASCII format that is amenable to taking a line and using a
regexp to break it down to its constituent fields.

> So, if we go down the path proposed in draft-gurbani-..., we're
> strapped with coming up with the perfect set of future-proof fields
> that encompasses everything anyone will ever need in the log file,
> while (at the same time) not including extraneous information that
> people don't want to bother generating and/or parsing.

I don't think we are constrained to a perfect set of future-proof
fields.  Rather, I think that there should be a list of fields
that are mandatory -- and these fields should be the ones that
allow for dialog and transaction identification and correlating
the various forked branches to a parent transaction, etc.

Regarding people don't wanting to get bothered by generating
and/or parsing extra fields, even in the currently
defined ASCII format, there is a delimiter after which the
rest of the fields are optional.  An off-the-shelf open source
CLF parser can parse all the mandatory ones and can just
disregard the optional ones; no harm done.  Of course, since
it will be written most probably in an interpreted language
of some sort (and I am thinking of perl/python here), it could
be extended to more easily to parse these fields.

Remember that we are not the consumers of the log file, rather
it is the people who will be feeding SIP servers.  And given
that constituency, I think they'd rather prefer to write tools
that operate on ASCII.

> The binary format I've proposed allows for exclusion of information
> the logging node doesn't consider relevant, as well as inclusion of 
> information that we don't define at this time. For me, that's almost
> as big a win as the efficiency in searching a file for records of
> interest.

Given the updated results and all, I will stop arguing on the
grounds of efficiency.  Reading binary CLF was always more
efficient, and so is producing the binary CLF.  But if the
only CLF format we define is a binary CLF, then I want to be
clear that we understand that we are making a tacit decision
to force all implementations to deal with digesting their SIP
message in this new format for logging purpose.  There will be
some SIP servers that already digest the incoming SIP message
and turn it into binary (complete with a ToC) for efficient
memory copying, etc.  To these servers, producing a binary CLF
will be a low impact activity.  But, there are and will be
SIP servers that do not carry an internal binary representation
of the SIP message.  We will, in essence, force these servers
to do so just to produce binary CLF.  And that is a big tradeoff.

A binary CLF can always be produced from an ASCII one using
offline transformations.  It is just that producing an ASCII
CLF is low-impact since the messages that enter and exit
a SIP server are ASCII to begin with.

Before going down the path of mandating a binary-only option,
I would at the very least like us to understand the tradeoffs
of the decision and keep in mind who the ultimate consumers
of the log file are.

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: Theo Zourzouvillys <[email-masked]>
Date: Thu, 30 Apr 2009 23:03:03 +0100

On Thu, Apr 30, 2009 at 10:12 PM, Vijay K. Gurbani
<[email-masked]> wrote:

> offline transformations.

indeed, and a binary one can be just as easily converted to an ASCII
one - quicker in that direction, too :-)

> It is just that producing an ASCII

this statement makes no sense at all in the context of this dicussion.

it's not like there is a 1:1 mapping between the memory chunk received
over a network card and the log line.  Be it ASCII or binary, it needs
to generate the record.  Both are as simple as each other, whatever
the scenario.

 ~ Theo

-- 
http://twitter.com/zourzouvillys
http://crazygreek.co.uk/

Sent from Bicester, Oxfordshire, United Kingdom

---

From: Adam Roach <[email-masked]>
Date: Thu, 30 Apr 2009 17:18:53 -0500

> regexp to break it down to its constituent fields.

That's going to be pretty difficult with character escaping. You'll need 
powerful regex ninja skills to deal with the text format once you figure 
out how to handle things like spaces embedded within fields.

> that constituency, I think they'd rather prefer to write tools

I don't think the constituent consumers will be particularly upset by 
the difference between:

   grep [email-masked]' sip-clf.log

and

   clfdump sip-clf.log | grep [email-masked]'

> efficient, and so is producing the binary CLF.
...
> But, there are and will be

That's pure nonsense. You first acknowledge that the proposed binary 
format is faster to read and faster to write... and then make an 
argument that seems to be predicated on the opposite of that fact.

The servers will need to separate the components of interest out for 
both the format described in your document and the format described in 
mine. The binary format doesn't take any ASCII fields and turn them into 
a binary representation (with the exception of CSeq, but a single 
string-to-integer transformation -- one that almost every implementation 
needs to perform anyway -- certainly can't be what you're objecting to). 
The only real processing difference is how field and record delimitation 
is handled -- and we already know that the speed differences between 
them are negligible.

> A binary CLF can always be produced from an ASCII one using

And vice-versa -- at least, modulo the extensible tagging mechanisms 
inherent in the binary format.

> a SIP server are ASCII to begin with.

Unless you're dumping literal SIP messages (which is not what you're 
proposing), you're still having to parse out the fields and rearrange 
them. This is true for BOTH formats. The impact is not significantly 
higher for one versus the other, and you've acknowledged that empirical 
data confirms this fact.

> of the decision and keep in mind who the ultimate consumers

While I'm sure some of the ops guys will appreciate the fact that they 
get to take a 20-minute coffee and/or smoking break every time they 
launch a query against a 60-million-record log, there's probably a 
larger percentage of them who would like to be able to do their jobs 
efficiently.

At least, that's what I suspect.

/a

---

From: Adam Roach <[email-masked]>
Date: Thu, 30 Apr 2009 18:34:49 -0500

> one - quicker in that direction, too :-)

In fact, I'll help you out here.

/a

------------------------------------------------------------------------
#!/usr/bin/perl

$bin = shift;

open(LOGFILE, $bin) or die("Could not open log file $bin.");

while (read(LOGFILE, $buffer, 4) == 4)
{
   $tmp = unpack('N',$buffer) ;
   $rec_len = $tmp & 0x7FFF;
   $flags = $tmp >> 24;

   read(LOGFILE,$buffer,$rec_len-4) || die $!;
   ($date_hi, $date_lo, $time_ns, $cseq, $resp_code, $tlv_ptr, @toc)
     = unpack ('N4n18',$buffer);
   $tlv = substr($buffer, $tlv_ptr-4);

   if ($flags & &RESPONSE_FLAG)
   {
     #%d %x %y %s %m %t "%c"
     printf ("%s %s %s %03.3d %s %s;tag=%s \"%s\"\n",
             ($date_hi<<32|$date_lo),
             &get_field(&SERVER_TXN_FIELD,$buffer,@toc),
             &get_field(&CLIENT_TXN_FIELD,$buffer,@toc),
             $resp_code,
             &get_field(&METHOD_FIELD,$buffer,@toc),
             &get_field(&TO_FIELD,$buffer,@toc),
             &get_field(&TO_TAG_FIELD,$buffer,@toc),
             &get_tlv(&CONTACT_TAG,$tlv));
   }
   else
   {
     #%d %h %u %m %r %f %t %i "%c" %x %y
     printf ("%s %s %s %s %s %s;tag=%s %s;tag=%s %s \"%s\" %s %s\n",
             ($date_hi<<32|$date_lo),
             &get_tlv(&REMOTE_HOST_TAG,$tlv),
             &get_tlv(&AUTH_USER_TAG,$tlv),
             &get_field(&METHOD_FIELD,$buffer,@toc),
             &get_tlv(&REQUEST_URI_TAG,$tlv),
             &get_field(&FROM_FIELD,$buffer,@toc),
             &get_field(&FROM_TAG_FIELD,$buffer,@toc),
             &get_field(&TO_FIELD,$buffer,@toc),
             &get_field(&TO_TAG_FIELD,$buffer,@toc),
             &get_field(&CID_FIELD,$buffer,@toc),
             &get_tlv(&CONTACT_TAG,$tlv),
             &get_field(&SERVER_TXN_FIELD,$buffer,@toc),
             &get_field(&CLIENT_TXN_FIELD,$buffer,@toc));
   }
}

sub RESPONSE_FLAG {0x80}
sub RETRANSMISSION_FLAG {0x40}
sub SENT_FLAG {0x20}

sub CONTACT_TAG {0}
sub REQUEST_URI_TAG {1}
sub REMOTE_HOST_TAG {2}
sub AUTH_USER_TAG {3}
sub WHOLE_MESSAGE_TAG {4}

sub SERVER_TXN_FIELD {0}
sub CLIENT_TXN_FIELD {1}
sub METHOD_FIELD {2}
sub TO_FIELD {3}
sub TO_TAG_FIELD {4}
sub FROM_FIELD {5}
sub FROM_TAG_FIELD {6}
sub CID_FIELD {7}

sub get_field
{
   my ($field, $buffer, @toc) = @_;
   my ($pointer, $length) = ($toc[$field*2],$toc[$field*2+1]);
   my $result = substr($buffer, $pointer-4, $length);
   if ($result) { return $result; }
   return '-';
}

sub get_tlv
{
   my ($search_tag, $tlv) = @_;
   my (@result, $tag, $len, $value);
   my $offset = 0;

   while ($offset < length($tlv))
   {
     ($tag, $len) = unpack ('n2',substr($tlv,$offset));
     $value = substr($tlv, $offset + 4, $len);
     if ($tag == $search_tag) { push @result, $value }
     $offset += $len + 4;
   }

   if (@result) { return join ',',@result };
   return "-";
}

---

From: "Scott Lawrence" <[email-masked]>
Date: Thu, 30 Apr 2009 20:49:53 -0400

> out how to handle things like spaces embedded within fields.

Not to mention escaped double quotes.

Having done a regex-based parser for just name-addr, I'd say don't go
there.