Subject: [sip-clf] Ugly examples from the SIP torture test

From: Saverio Niccolini <[email-masked]>
Date: Wed, 11 Aug 2010 16:45:20 +0000

Dear all,

from the minutes I read (again):
"Robert: Really want to see the ugly examples from the SIP torture test."

Can somebody explain me what is the point of doing this?
I do not see the value of doing this...

I think it is much more useful to give readable examples to have
people realize what the SIPCLF log will look like.

I mean SIP torture tests are meant to stress parsers not SIPCLF 
loggers, thus if a parser is handling the case, then the SIPCLF 
module after the parser will handle it... 

Thanks,
Saverio

============================================================
Dr. Saverio Niccolini
Manager, Real-Time Communications Group
NEC Laboratories Europe, Network Research Division     
Kurfuerstenanlage 36, D-69115 Heidelberg
Tel.     +49 (0)6221 4342-118
NEC*NET Phone: 800-49-33-118
Fax:     +49 (0)6221 4342-155
e-mail:  [email-masked]
============================================================
NEC Europe Limited Registered Office: NEC House, 1 Victoria
Road, London W3 6BL Registered in England 2832014

---

From: Mary Barnes <[email-masked]>
Date: Wed, 11 Aug 2010 13:50:01 -0500

Saverio,

My understanding is that the motivation for including torture tests is
because the logs are quite valuable in the cases where things go wrong.  If
you can show what the logs should look like for some of those examples, it
will help folks debug some of those use cases.  When I have used SIP logs,
they are sometimes useful for figuring out stats, however, my most common
usage is when things don't seem to be working quite right.  The problem
statement includes (cursory) Troubleshooting as a potential usage of the
logs, so I think it's entirely appropriate (and useful) to include these
examples.

Regards,
Mary.

On Wed, Aug 11, 2010 at 11:45 AM, Saverio Niccolini <
[email-masked]> wrote:

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

---

From: Peter Musgrave <[email-masked]>
Date: Wed, 11 Aug 2010 15:49:21 -0400

My understanding was that this might also expose issues in the formats
- in terms of setting minimum sizes for some elements (since e.g.
indexed ASCII has pointer blocks - which imply max sizes and the IPFIX
total message is 64K - so there may be cases where that becomes an
issue - in which case a decision to truncate or extend over multiple
IPFIX records might be required).

Peter Musgrave
(as individual)

On Wed, Aug 11, 2010 at 2:50 PM, Mary Barnes <[email-masked]> wrote:
> On Wed, Aug 11, 2010 at 11:45 AM, Saverio Niccolini
> <[email-masked]> wrote:
>>
>> Dear all,
>>

---

From: Brian Trammell <[email-masked]>
Date: Thu, 12 Aug 2010 09:58:02 +0200

Hi, all,

In brief, I don't think the issue is torture tests per se -- we absolutely do need to probe the limits of each _representation_ in order to discover where they fall over -- but that the torture tests in RFC 4475 have a different set of requirements that those that would test the limits of logging, especially at this stage in the game. 4475 is designed to test implementations, not representations. Definitely in the case of IPFIX, probably in the case of indexed-ascii, too, what we're testing then is not the log representation, but the implementation of the parser on the front of the thing that shovels data into the log. Indeed, many of the more interesting parts of 3.1.1.2 "Wide Range of Valid Characters" don't have any affect on the log at all, because they impact fields that are not represented in the data model.

(As an aside, this probably speaks well of the value of 4475. They're such good SIP parser tests that they test your SIP parser even when that's not what you want them to do.)

Detailed replies inline.

Best regards,

Brian

> IPFIX records might be required).

Okay. Then let's specify tests designed to push those bounds - one with nulls in strings, overlength strings, >64k entities,  etc. But the 4475 tests specify what a _parser_ should do, not what the content of the resulting _log_ should be. On second thought, this probably needs to be specified: i.e., do I have to re-escape a URI to make it canonical, even if I'm using a binary representation? I have no idea what the  We can certainly base these on the 4475 tests, but just throwing 4475 at the two reps won't, I think, test out the actual differences between them.

Before knowing what the acceptance criteria for these tests are, we still need to have the talk about limits.

>> logs, so I think it's entirely appropriate (and useful) to include these

Absolutely. But troubleshooting means a lot of things. There's the "troubleshooting a complex interaction across multiple entities that causes something to go subtly wrong"; here, you _need_ a standard log format so you can trace things from vendor A box to vendor B box to vendor C box. There's "troubleshooting handling of bad SIP"; this is where 4475 comes in, and gets back to my earlier comment about the difference between an access log and an error log. Here you can log the parsed down version but if the incoming message is malformed, the parsed-down version may or may not  Then there's "debugging an implementation", where you probably want implementation specific details; you can add these inline with your own enterprise-specific Information Elements but if you're anything like me you'll probably just be lazy and stick a bunch of fprintfs to stderr in the code.

We can certainly handle all of these use cases with IPFIX; for the "things are seriously broken, I'm giving up" case I'd probably recommend adding sipRawMessageSection, sipRawMessageSectionOffset, and sipRawMessageLength IEs, and a special-case template, so that an implementation can just dump a truncated or split (across multiple 64k IPFIX messages) raw message for detailed analysis.

---

From: Robert Sparks <[email-masked]>
Date: Tue, 17 Aug 2010 20:30:04 -0500

Really - is running 3.1.1.2 through and producing a representation so hard no one is willing to do it?
If so, that's a red flag for me.

The point is exactly to sanity check that everyone has the same idea about how some of the unusual
things will get captured (and that it is actually possible to capture them).

I'm not asking that it live forever in the draft or that it be the place that folks stop - in fact Brian's point 
that some of the unusual, but legal, things that can happen in messages aren't happening in fields
that get logged is a good one. Before we're done, someone should stretch the other limits. 

But to start, run some of the messages like 3.1.1.2 through and make sure nobody is surprised by the output.
Just sending the results to the list should be enough for us to know if we're all on the same page.

RjS

---

From: Gonzalo Salgueiro <[email-masked]>
Date: Tue, 17 Aug 2010 23:26:49 -0400

Robert - 

No red flags needed :-)

I very quickly did a manual decode of the message in 3.1.1.2 of RFC4475 for the indexed-ASCII representation using the syntax in the -01 version. I plan to add it to the next version of the draft. As you mention, I suspect there is no need to have those messages in later versions as the draft progresses.

Gonzalo

Note: there are non-printable characters in the record below (hex 00, etc.) so the base-64 encoding is also provided

A000269,Ros,0071003500A7006B01130014012E00140149005901A30079021C002A0247000102490001024B0013025F
1282085075.323	139122385 !interesting-Method0123456789_*+`.%indeed'~	sip:1_unusual.URI~(to-be!sure)&isn't+it$/crazy?,/;;*:&it+has=1,weird!*pas$wo~d_too.(doesn't-it)@example.com	host2.example.com:5060:tcp	host1.example.com:5060:tcp	"BEL:\ NUL:\ DEL:\" <sip:1_unusual.URI~(to-be!sure)&isn't+it$/crazy?,/;;[email-masked]>	token1~` token2'+_ token3*%!.- <sip:[email-masked]>;fromParam''~+*_!.-%="работающий";tag=_token~1'+`*%!-.	intmeth.word%ZK-!.*_+'@word`~)(><:\/"][?}{	-	-	z9hG4bK-.!%66*_+`'~	0001,000C,192.168.1.15

begin-base64 600 intmeth.clf
====

---

From: Brian Trammell <[email-masked]>
Date: Wed, 18 Aug 2010 08:53:14 +0200

Hi Robert, all,

> If so, that's a red flag for me.

The next rev of the ipfix doc (submission shortly) has a 3.1.1.2 example.

Understand that the implementation we have now, as IPFIX people with limited understanding of the minutiae of SIP escaping (which is admittedly a bit odd), pokes raw bytes into a string then builds an IPFIX Message out of that. The difficulty isn't in the logging, it's in the trying to reason about what exactly goes into the log in the first place. Once you've done that though, it's quite simple.

If we were hitching the IPFIX backend to an actual SIP implementation that had already passed 4475, this would be another story.

> things will get captured (and that it is actually possible to capture them).

I think here is where we'll have interesting discussion and better opportunities for convergence: for example, looking at Gonzalo's example, there seems to be a disagreement between indexed-ascii and IPFIX as to what a From URI and To URI are, and I'm still not satisfied as to what should happen with illegal methods.

> that get logged is a good one. Before we're done, someone should stretch the other limits. 

Absolutely. 

> Just sending the results to the list should be enough for us to know if we're all on the same page.

Okay, good. Done. We also did 3.1.1.4 (a rather simple case for _parsing_ but one that might in our estimation tease out issues in logging and log reading). 

The multipart body example will follow in a subsequent revision (I think we want to complete the discussion on limits, first). Again, here, the question is as to what should be done with the multipart body itself. The only interesting part of this example from an IPFIX standpoint would appear to be the size limitation, for which we have a discussion but no example yet. (And this is more a question of determining how to generate and present the example than it is a question of engineering the proposed solution -- I presume we don't want 80k of base64 in an appendix at this point...)

Best regards,

Brian

---

From: Hadriel Kaplan <[email-masked]>
Date: Wed, 18 Aug 2010 20:08:26 -0400

One question on the topic of the torture tests, though not directly, is at what "layer" or processing step we're doing this logging.  For example, if a URI has % escaped characters like "%07", do we log the UTF-8 literals we received as in "%07" in the log, or do we log the binary 0x07?  It matters in order to have consistency among different implementations, especially with normally escaped characters for embedded headers in URIs.

I think the right answer is the sipclf should have the literal UTF-8 as they were received/sent, i.e. the three utf-8 characters "%07".  That way no matter whether you are a proxy ignoring things as opaque strings, or a UA and interpreting them, they are recorded the same.

-hadriel

---

From: Peter Musgrave <[email-masked]>
Date: Thu, 19 Aug 2010 06:10:49 -0400

I'd favour logging things in as close to "one the wire" form as
possible. So I agree that logging should be of the UTF-8 literals.

Peter

---

From: "Vijay K. Gurbani" <[email-masked]>
Date: Thu, 19 Aug 2010 08:22:31 -0500

On 08/18/2010 07:08 PM, Hadriel Kaplan wrote:
> I think the right answer is the sipclf should have the literal UTF-8
> as they were received/sent, i.e. the three utf-8 characters "%07".
> That way no matter whether you are a proxy ignoring things as opaque
> strings, or a UA and interpreting them, they are recorded the same.

I agree.

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: Dan Burnett <[email-masked]>
Date: Mon, 30 Aug 2010 17:21:59 -0400

+1
Literal is best.

-- dan

On Aug 18, 2010, at 8:08 PM, Hadriel Kaplan wrote:

>
> One question on the topic of the torture tests, though not directly,  
> is at what "layer" or processing step we're doing this logging.  For  
> example, if a URI has % escaped characters like "%07", do we log the  
> UTF-8 literals we received as in "%07" in the log, or do we log the  
> binary 0x07?  It matters in order to have consistency among  
> different implementations, especially with normally escaped  
> characters for embedded headers in URIs.
>