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

Brian Trammell <trammell@tik.ee.ethz.ch> Wed, 18 August 2010 06:52 UTC

Return-Path: <trammell@tik.ee.ethz.ch>
X-Original-To: sip-clf@core3.amsl.com
Delivered-To: sip-clf@core3.amsl.com
Received: from localhost (localhost [127.0.0.1]) by core3.amsl.com (Postfix) with ESMTP id 37CB53A690A for <sip-clf@core3.amsl.com>; Tue, 17 Aug 2010 23:52:43 -0700 (PDT)
X-Virus-Scanned: amavisd-new at amsl.com
X-Spam-Flag: NO
X-Spam-Score: -4.094
X-Spam-Level:
X-Spam-Status: No, score=-4.094 tagged_above=-999 required=5 tests=[AWL=1.905, BAYES_00=-2.599, J_CHICKENPOX_33=0.6, RCVD_IN_DNSWL_MED=-4]
Received: from mail.ietf.org ([64.170.98.32]) by localhost (core3.amsl.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 12LWZZQZ-OvU for <sip-clf@core3.amsl.com>; Tue, 17 Aug 2010 23:52:41 -0700 (PDT)
Received: from smtp.ee.ethz.ch (smtp.ee.ethz.ch [129.132.2.219]) by core3.amsl.com (Postfix) with ESMTP id 8C4623A68F3 for <sip-clf@ietf.org>; Tue, 17 Aug 2010 23:52:41 -0700 (PDT)
Received: from localhost (localhost [127.0.0.1]) by smtp.ee.ethz.ch (Postfix) with ESMTP id EAA41D938F; Wed, 18 Aug 2010 08:53:15 +0200 (MEST)
X-Virus-Scanned: by amavisd-new on smtp.ee.ethz.ch
Received: from smtp.ee.ethz.ch ([127.0.0.1]) by localhost (.ee.ethz.ch [127.0.0.1]) (amavisd-new, port 10024) with LMTP id IKuOQcH-JmDN; Wed, 18 Aug 2010 08:53:15 +0200 (MEST)
Received: from [10.0.1.11] (80-218-71-226.dclient.hispeed.ch [80.218.71.226]) (using TLSv1 with cipher AES128-SHA (128/128 bits)) (No client certificate requested) (Authenticated sender: briant) by smtp.ee.ethz.ch (Postfix) with ESMTPSA id 63304D938C; Wed, 18 Aug 2010 08:53:15 +0200 (MEST)
Mime-Version: 1.0 (Apple Message framework v1081)
Content-Type: text/plain; charset="us-ascii"
From: Brian Trammell <trammell@tik.ee.ethz.ch>
In-Reply-To: <F1579CC7-B4F2-4642-8093-9FB0A3CE9A51@nostrum.com>
Date: Wed, 18 Aug 2010 08:53:14 +0200
Content-Transfer-Encoding: quoted-printable
Message-Id: <6271DD79-C9AF-4A56-B63D-ADF1B65A4779@tik.ee.ethz.ch>
References: <752EDF9B02C09847950620E262C45431640FBF@PALLENE.office.hd> <AANLkTinRgrexMbiqzBtf+dCsX+5BcWjOYMYo6yPj+7s3@mail.gmail.com> <AANLkTikkkUpKGSGYi8Tixkeu6_svvu47BiKM-ZWL9Tfh@mail.gmail.com> <9280DBAC-F20E-4556-A39E-CDC0780D9838@tik.ee.ethz.ch> <F1579CC7-B4F2-4642-8093-9FB0A3CE9A51@nostrum.com>
To: Robert Sparks <rjsparks@nostrum.com>
X-Mailer: Apple Mail (2.1081)
Cc: "sip-clf@ietf.org" <sip-clf@ietf.org>, Saverio Niccolini <Saverio.Niccolini@neclab.eu>
Subject: Re: [sip-clf] Ugly examples from the SIP torture test
X-BeenThere: sip-clf@ietf.org
X-Mailman-Version: 2.1.9
Precedence: list
List-Id: SIP Common Log File format discussion list <sip-clf.ietf.org>
List-Unsubscribe: <https://www.ietf.org/mailman/listinfo/sip-clf>, <mailto:sip-clf-request@ietf.org?subject=unsubscribe>
List-Archive: <http://www.ietf.org/mail-archive/web/sip-clf>
List-Post: <mailto:sip-clf@ietf.org>
List-Help: <mailto:sip-clf-request@ietf.org?subject=help>
List-Subscribe: <https://www.ietf.org/mailman/listinfo/sip-clf>, <mailto:sip-clf-request@ietf.org?subject=subscribe>
X-List-Received-Date: Wed, 18 Aug 2010 06:52:43 -0000

Hi Robert, all,

On Aug 18, 2010, at 3:30 AM, Robert Sparks wrote:

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

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

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

Absolutely. 

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

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

> RjS
> 
> On Aug 12, 2010, at 2:58 AM, Brian Trammell wrote:
> 
>> 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
>> 
>> On Aug 11, 2010, at 9:49 PM, Peter Musgrave wrote:
>> 
>>> 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).
>> 
>> 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.
>> 
>>> Peter Musgrave
>>> (as individual)
>>> 
>>> On Wed, Aug 11, 2010 at 2:50 PM, Mary Barnes <mary.ietf.barnes@gmail.com> wrote:
>>>> 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.
>> 
>> 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. 
>> 
>>>> On Wed, Aug 11, 2010 at 11:45 AM, Saverio Niccolini
>>>> <Saverio.Niccolini@neclab.eu> wrote:
>>>>> 
>>>>> 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:  saverio.niccolini@neclab.eu
>>>>> ============================================================
>>>>> NEC Europe Limited Registered Office: NEC House, 1 Victoria
>>>>> Road, London W3 6BL Registered in England 2832014
>>>>> 
>>>>> 
>>>>> 
>>>>> 
>>>>> 
>>>>> _______________________________________________
>>>>> sip-clf mailing list
>>>>> sip-clf@ietf.org
>>>>> https://www.ietf.org/mailman/listinfo/sip-clf
>>>>> 
>>>> 
>>>> 
>>>> _______________________________________________
>>>> sip-clf mailing list
>>>> sip-clf@ietf.org
>>>> https://www.ietf.org/mailman/listinfo/sip-clf
>>>> 
>>>> 
>>> _______________________________________________
>>> sip-clf mailing list
>>> sip-clf@ietf.org
>>> https://www.ietf.org/mailman/listinfo/sip-clf
>> 
>> _______________________________________________
>> sip-clf mailing list
>> sip-clf@ietf.org
>> https://www.ietf.org/mailman/listinfo/sip-clf