Subject: [Sipping] Alternate CLF syntax proposal

From: Adam Roach <[email-masked]>
Date: Wed, 25 Mar 2009 19:02:04 -0700

In the spirit of "send text," I've put together a straw-man proposal for 
an easy-to-generate and fast-to-process extensible format for saving SIP 
log messages:

http://www.ietf.org/internet-drafts/draft-roach-sipping-clf-syntax-00.txt

As an example of the processing that can be performed on this format: 
consider that I have a large file (on the order of 1 GB of data), with 
1,232,896 records in it (to choose a nice, round number). I'd like to 
extract all the information about messages with a particular "From" value.

With a text-based format, I'll be reading and parsing 1,262,485,504 
bytes (every byte in the file) in order to find delimiters.

With the format proposed in this document, I can open the file and then 
do the following about 1,232,896 times:

  - Read 4 bytes (total record length)
  - Fseek 32 bytes to reach the "To Value" pointer and length
  - Read 4 bytes
  - Fseek according to those 4 bytes to the literal value of the to 
header field
  - Read the to header field (let's imagine it's 20 bytes)
  - Fseek to the next record (according to the total record length)

In total, I'm reading 28 bytes per record 1,232,896 times, for a grand 
total of 34,521,088 bytes -- or about 2.7% as much data as I do with a 
text file.

When you're dealing with terabytes of log data, this can make the 
difference between taking one minute to sift data and taking 37 minutes 
to do the same operation. And, of course, it has the advantage that you 
can add more (tagged) data to each record without causing any additional 
processing load.

/a

---

From: "Vijay K. Gurbani" <[email-masked]>
Date: Wed, 25 Mar 2009 21:58:03 -0500

> http://www.ietf.org/internet-drafts/draft-roach-sipping-clf-syntax-00.txt
[...]

Adam: Essentially you are advocating for a table-of-content
type of approach where you read the ToC and index straight
to where you want to go.  I have worked on SIP parsers
designed this way.

The parsing is optimized, yes, when compared to the ASCII
version -- though perl can do wonders, but not to outperform
binary parsing.  The disadvantage is that you loose readability
and would need specialized tools to, say, grep through such
a file.

It will be interesting to see what others think...

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: Jason Fischl <[email-masked]>
Date: Thu, 26 Mar 2009 08:36:10 -0700

On Wed, Mar 25, 2009 at 7:02 PM, Adam Roach <[email-masked]> wrote:

> In the spirit of "send text," I've put together a straw-man proposal for an
> easy-to-generate and fast-to-process extensible format for saving SIP log
> messages:
>

I quite like this scheme. It is very simple to generate and parse and will
be blazingly fast. It would also be very simple to create a utility to
generate "human-readable" versions from it which would address that
particular concern.

Comments about the format:
- add a version number to the header
- set aside a range of tags for vendor attributes.

A few miscellaneous comments about contents:
- for sent messages: local ip:port used to send the message + transport used
+ destination ip:port
- for received messages: remote ip:port message was received from + local
ip:port + transport used
- it may be a good idea to have a predefined tag which can be used as an
index into another diagnostic file. e.g. pointer into a PCAP file or vendor
diagnostic log.
- Is there anything we want to jam in here to help debug TCP/TLS issues or
is that out of scope?

Jason

---

From: Hadriel Kaplan <[email-masked]>
Date: Thu, 26 Mar 2009 15:56:51 -0400

If the purpose of it is troubleshooting, or threat analysis type stuff, I think the following format satisfies the needs as well:
http://wiki.wireshark.org/Development/LibpcapFileFormat

The advantages:
1) There's running code
2) There's open source, on all operating systems, and also for commercial use
3) It's used by many people
4) There are many tools which accept/process it
5) It's fast to write/save
6) It supports a sub-second timestamp
7) It supports length encoding of packets, so you can skip past them
8) It supports truncated saving of packets, so you don't have to save all of very big ones 
9) It records the method name or response code very early in the saved log entry for each packet

Disadvantages:
1) Nothing much new to specify, except to document it? 
2) It's a little tricky for SIP/TLS, where you basically have to create fake segments/packets for the low layers, and same may be true for SIP/TCP depending on when you record the log
3) It doesn't provide a way to report internal system events/actions/info (although we could fix that)
4) Afaik, there is no specific remote push/streaming mechanism for it defined (there was an attempt at it, but not final)

-hadriel

> -----Original Message-----
> From: [email-masked] [mailto:[email-masked]] On Behalf
> Of Vijay K. Gurbani
> Sent: Wednesday, March 25, 2009 10:58 PM
> 
> Adam Roach wrote:
> _______________________________________________
> Sipping mailing list  https://www.ietf.org/mailman/listinfo/sipping
> This list is for NEW development of the application of SIP
> Use [email-masked] for questions on current sip
> Use [email-masked] for new developments of core SIP

---

From: Hadriel Kaplan <[email-masked]>
Date: Thu, 26 Mar 2009 17:06:05 -0400

Actually, ya know we can combine this with something like Adam's draft.
If you take the pcap entry format, and encode a "log" entry with the following header:

|   0    |   1    |   2    |   3    |   4    |   5    |   6    |   7    |
-------------------------------------------------------------------------
|                           seconds                                     |
-------------------------------------------------------------------------
|                         microseconds                                  |
-------------------------------------------------------------------------
|                           saved_len                                   |
-------------------------------------------------------------------------
|                           orig_len                                    |
-------------------------------------------------------------------------
|                           all 0x00                                    |
-------------------------------------------------------------------------
|             0x00                  |     0x0800      |    0x4500       |
-------------------------------------------------------------------------
| log_entry_len   |    seq_no       |        0x000001         | 0x11    |
-------------------------------------------------------------------------
|                              all 0x00                                 |
-------------------------------------------------------------------------
|      0x00       |    0x0715       |    0x0715       |  entry_len      |
-------------------------------------------------------------------------
|      0x00       |  0x04  | 0x00   |      tot_len    |     0x0000      | 
-------------------------------------------------------------------------
|            all 0x00                                 |   BEGIN         |
-------------------------------------------------------------------------

Then starting with the BEGIN bytes, you can record each Tag-Length-Value triple using the following:
1-Byte Type
1-byte Length (including type and length bytes)
1-255 bytes of chars

And once again there would be plenty of tools/running-code which can already parse that today.  :)

Or we could do a slightly different variant of the "header", if you want TLV's which can be bigger/longer.

-hadriel

> Of Hadriel Kaplan
> Sent: Thursday, March 26, 2009 3:57 PM
> To: Vijay K. Gurbani; Adam Roach
> Cc: sipping WG; [email-masked]
> Subject: Re: [Sipping] Alternate CLF syntax proposal
> 
> 
> If the purpose of it is troubleshooting, or threat analysis type stuff, I
> think the following format satisfies the needs as well:
> 2) It's a little tricky for SIP/TLS, where you basically have to create
> fake segments/packets for the low layers, and same may be true for SIP/TCP
> depending on when you record the log
> 4) Afaik, there is no specific remote push/streaming mechanism for it
> defined (there was an attempt at it, but not final)
> 
> -hadriel
>

---

From: Hadriel Kaplan <[email-masked]>
Date: Thu, 26 Mar 2009 21:16:43 -0400

BTW, the below would be parsed as a RADIUS Accounting message.
So essentially what this could mean is the "log file" entry format is a pcap packet format, one "capture packet" per log entry.  You could encode the whole SIP message in such as usual, including real IP/UDP headers, or you could encode what effectively looks like a RADIUS message in such to encode specific TLV's (Radius Attributes) - or you can do *both* in the same log stream.  

Or if we think 255 attributes of up to 255 octets each is not enough, one could encode it as DIAMATER messages - again you're not running DIAMETER, it's just an encoding format that supports TLV's which happens to look like DIAMETER for tools receiving it, without actually running RADIUS/DIAMETER and thus without the responses and application of those - just streamed log entries.

Just a whacky idea, probably.  But there sure is a lot of available, running code for this.

-hadriel

> From: Hadriel Kaplan
> Sent: Thursday, March 26, 2009 5:06 PM
> To: Hadriel Kaplan; Vijay K. Gurbani; Adam Roach
> Subject: RE: [Sipping] Alternate CLF syntax proposal
> 
> 
> > 2) There's open source, on all operating systems, and also for
> commercial
> > use
> > 8) It supports truncated saving of packets, so you don't have to save
> all
> > of very big ones
> > 9) It records the method name or response code very early in the saved
> log
> > entry for each packet
> >
> > Disadvantages:
> > 3) It doesn't provide a way to report internal system
> events/actions/info
> > (although we could fix that)

---

From: Theo Zourzouvillys <[email-masked]>
Date: Sun, 29 Mar 2009 11:26:39 +0100

> generate "human-readable" versions from it which would address that

I also really like Adam's binary proposal and would much prefer we
progress down a binary path instead of plain text.  My reasoning is
that the point of standardising such a format would be for analysis or
monitoring/diagnostics, which would inherently be processed by
machines, not humans.  The only advantage of a text format is for tail
-f'ing on a live server;  such a thing has no reason to be
standardised short of the operator in question knowing which fields
are which in the same way i do when tailing an access.log.  This is
commonly done by something such as:

 LogFormat "%h %l %u %t \"%r\" %>s %b" common

and can easily be changed to include other stuff on a
per-server/implementation basis, i.e:

 LogFormat "%v %h %l %u %t \"%r\" %>s %b \"%{Referer}i\"
\"%{User-Agent}i\" VLOG=%{VLOG}e" vhost

However, the format which would be processed by collectors, stored,
analysed, and possibly post-processed or merged with others would
really want to be binary.  We currently use our own format internally
for transmitting between exporters and collectors and it would be nice
to see a standardised format so we can perhaps build some open source
analysis tools that would work with multiple vendors or a collector
that provides nice network statistics.

> - set aside a range of tags for vendor attributes.

yup, and in addition, i would like to see an exporter identifier.

> - Is there anything we want to jam in here to help debug TCP/TLS issues or

.. infact, come to think of it, IPFIX (RFC5101) seems perfect for all
of this - It would even allow encoding lower level data should you
want to such as ICMP type/code, source/dst IP, interfaces, or TCP/TLS
packet, SYN/ACK/RST events etc.

all we'd need to do is define a bunch of IEs in a document, and the
rest would "just work" (tm).

 ~ Theo

Sent from: Bicester Oxfordshire United Kingdom.

---

From: Jiri Kuthan <[email-masked]>
Date: Sun, 29 Mar 2009 21:35:23 +0200

Theo Zourzouvillys wrote:
> I also really like Adam's binary proposal 

Why aren't we happy then just with PCAP -- that's a de-facto standard.

-jiri

---

From: Theo Zourzouvillys <[email-masked]>
Date: Mon, 30 Mar 2009 03:50:54 +0100

> Why aren't we happy then just with PCAP -- that's a de-facto standard.

what does the pcap format give us? see:

... it doesn't really solve any of the problems except provide a
struct header and record header, much of which we don't even need (and
missing stuff we do need).

We'd just be shoving whatever formats we defined into a record in
them.  None of the pcap tools would work on records except raw
packets, which most of the time i don't want to be collecting or
sending across the network to a collector - a port mirror already does
that pretty well :-)

 ~ Theo

---

From: Cullen Jennings <[email-masked]>
Date: Mon, 30 Mar 2009 13:06:11 -0600

I might not understand everything that is possible with pcap but it  
seems to me that the problem with PCAP is that it generally saves the  
whole SIP message if you want to get all the headers - Say for example  
an operator wants to log who sent INVITES to what what numbers and  
when the correlated BYE happened so  that they can debug stuff later.  
But they do not want to capture the IP addresses of the UAs because if  
they save them then they have to respond to court orders to provide  
the logs with IP in them which is just a huge pain for with the  
operator and does not provide any revenue. The other issue is that  
logging the complete messages is often just too much data.

I like the proposal - mostly I just want something that works in high  
performance systems.

Cullen in my individual contributor role.

---

From: "Daryl Malas" <[email-masked]>
Date: Mon, 30 Mar 2009 14:30:09 -0600

Cullen,

I agree with your assertion.  PCAP does capture everything, which is
great for debugging.  I would prefer to have a compromise between
Vijay's original proposal and PCAP.

Regards,

Daryl

----------------
Daryl Malas
CableLabs
(o) +1 303 661 3302
(f) +1 303 661 9199
mailto:[email-masked]

> From: [email-masked] 
> [mailto:[email-masked]] On Behalf Of Cullen Jennings
> Sent: Monday, March 30, 2009 1:06 PM
> To: sipping
> Cc: Jason Fischl; Adam Roach; [email-masked]
> I might not understand everything that is possible with pcap 
> but it seems to me that the problem with PCAP is that it 
> generally saves the whole SIP message if you want to get all 
> the headers - Say for example an operator wants to log who 
> sent INVITES to what what numbers and when the correlated BYE 
> happened so  that they can debug stuff later.  
> But they do not want to capture the IP addresses of the UAs 
> because if they save them then they have to respond to court 
> orders to provide the logs with IP in them which is just a 
> huge pain for with the operator and does not provide any 
> revenue. The other issue is that logging the complete 
> messages is often just too much data.
> 
> I like the proposal - mostly I just want something that works 
> in high performance systems.
> 
> >>> I quite like this scheme. It is very simple to generate and parse 
> >>> and will be blazingly fast. It would also be very simple 
> to create a 
> >>> utility to generate "human-readable" versions from it which would 
> >>> address that particular concern.
> > This list is for NEW development of the application of SIP Use 
> > [email-masked] for questions on current sip Use 
> > [email-masked] for new developments of core SIP
> 
> Use [email-masked] for questions on current 
> sip Use [email-masked] for new developments of core SIP
>

---

From: Hadriel Kaplan <[email-masked]>
Date: Mon, 30 Mar 2009 18:36:01 -0400

Pcap is just a file format. (well, technically it's an API library, but we're just talking about the pcap file format)  

The format of the file and its entries is ridiculously simple binary.  It has a 24 byte file header, and a 16-byte header per record entry.  Each record entry header has a timestamp, which is something I think we'd need for a CLF, and it has a length, which is something people said in the ad-hoc they'd like.

How we use such a format is actually up to us.  The fact that it follows a pcap file format can be purely coincidental.  If we want currently available tools which support pcap files to be able to read this formatted file, right now without any changes, then we'd have to be careful in what we put in each record after the per-record header.

-hadriel

> Of Cullen Jennings
> Sent: Monday, March 30, 2009 3:06 PM
> To: sipping
>

---

From: Hadriel Kaplan <[email-masked]>
Date: Tue, 31 Mar 2009 12:42:51 -0400

That depends on what you think a "Common Log Format" would be useful for.  The premise was that it's for troubleshooting and analysis systems.  AFAICT, nothing short of the entire SIP message sequence, including contents, and even IP/UDP or TCP headers, would be sufficient for that in practice.

But anyway, attached is an example CLF file using only the currently defined fields from draft-gurbani-sipping-clf-01, I think, encoded in a different format from the draft.  It just happens to be that there are already tools which can even read this file and allow the user to view its contents in a meaningful way.  For example, you can open this attachment in wireshark.

-hadriel

> Of Theo Zourzouvillys
> Sent: Sunday, March 29, 2009 10:51 PM
> To: Jiri Kuthan
> Cc: Jason Fischl; sipping WG; [email-masked];
> Adam Roach

---

From: Theo Zourzouvillys <[email-masked]>
Date: Tue, 31 Mar 2009 18:33:20 +0100

> That depends on what you think a "Common Log Format" would be useful for.  The premise was that it's for troubleshooting and analysis systems.  AFAICT, nothing short of the entire SIP message seque…

i think perhaps what i'm, after isn't "common log format", and instead
a "distributed event exporter/collector API" for network monitoring
and Complex Event Processing systems, and is almost certainly a
totally separate thing to be tackled another day :-)

> But anyway, attached is an example CLF file using only the currently defined fields from draft-gurbani-sipping-clf-01, I think, encoded in a different format from the draft.

The problem is this isn't really any different to the plain text
format, except it includes an initial packet length header and thus
you can skip over the whole record easily.  You still need to parse
the contents of the pacp record to match any information such as a
specific via header or to tag.  One thing that is nice about a fixed
format like adam's is you can convert an input criteria filter into a
set of opcodes that you can then further compile into local machine
code to scan through in a very, very efficient way, similar to how
packet capturing in the kernel or tcpdump (i.e, -dd) works.

saying that, i do prefer pcap over the plain text method...

 ~ Theo Kaplan