Data records for options templates (converted from NFv9) do not increase sequence number

ghost commented 8 years ago

Although we discovered the issue in the particular case of converting options templates from NFv9, the issue is more generic: the code in insert_timestamp_template and insert_timestamp_data, which keeps track of the sequence numbers during conversion, only works if data records feature timestamps (field ID 21 and 22). This is however not a given, especially not for options templates.

Traces for reproduction can be provided upon request.

jepries commented 8 years ago

I may be having this same issue, could you take a look at my analysis below and confirm? I need to create a workaround if this is the case.

I've added some debug messages in the code to trace this down where my error is occurring, it traces into the Options templates. I've added this debug statement which prints this warning to the screen:

DEBUG: UDP input: PRIES: Message Version: 9
DEBUG: convert: PRIES: NETFLOW_V9 Conversion: sysUpTime=3977944382, unixSecs=1456027925, timeHeader=1452049980618
DEBUG: convert: PRIES: Template ID=1, Number Elements=4
DEBUG: convert: PRIES: Template ID=65335, Number Elements=257
**DEBUG: convert: PRIES: Failure due to malicious flowset ID, len=130670**    
DEBUG: convert: PRIES: len=130670, templates.max=350, templates.cols=2
DEBUG: convert: Error at V9_OPT_TEMPLATE_SET_ID
WARNING: UDP input: Message conversion error; skipping message...

The bolded one above comes from the convert.c in this section

/* Input check: avoid overflow due to malicious flowset IDs */
if (len > templates.max * templates.cols) {
  /* JEP */
  MSG_DEBUG(msg_module, "PRIES: Failure due to malicious flowset ID, len=%lu", len);
  MSG_DEBUG(msg_module, "PRIES: len=%lu, templates.max=%lu, templates.cols=%lu", len, templates.max, templates.cols);
  return 1;
 }

I also printed out the received packet, this is what is incoming. If there is a workaround for this little problem I would sure appreciate it, otherwise I'll dig into the bits and try it out. The above debug output was produced by this incoming packet;

DEBUG: UDP input: PRIES: RECEIVED Packet: length=311
DEBUG: UDP input: PRIES: byte[0,1,2,3]: 0009 0004
DEBUG: UDP input: PRIES: byte[4,5,6,7]: ed1a 9d3e
DEBUG: UDP input: PRIES: byte[8,9,10,11]: 56c9 3915
DEBUG: UDP input: PRIES: byte[12,13,14,15]: 0001 1c2e
DEBUG: UDP input: PRIES: byte[16,17,18,19]: 0000 0000
DEBUG: UDP input: PRIES: byte[20,21,22,23]: 0001 001a
DEBUG: UDP input: PRIES: byte[24,25,26,27]: 0101 0004
DEBUG: UDP input: PRIES: byte[28,29,30,31]: 000c 0001
DEBUG: UDP input: PRIES: byte[32,33,34,35]: 0004 005f
DEBUG: UDP input: PRIES: byte[36,37,38,39]: 0004 0060
DEBUG: UDP input: PRIES: byte[40,41,42,43]: 0018 005e
DEBUG: UDP input: PRIES: byte[44,45,46,47]: 0037 0101
DEBUG: UDP input: PRIES: byte[48,49,50,51]: 0109 0303
DEBUG: UDP input: PRIES: byte[52,53,54,55]: 0303 0d00
DEBUG: UDP input: PRIES: byte[56,57,58,59]: 1466 786d
DEBUG: UDP input: PRIES: byte[60,61,62,63]: 7070 2d63
DEBUG: UDP input: PRIES: byte[64,65,66,67]: 6c69 656e
DEBUG: UDP input: PRIES: byte[68,69,70,71]: 7400 0000
DEBUG: UDP input: PRIES: byte[72,73,74,75]: 0000 0000
DEBUG: UDP input: PRIES: byte[76,77,78,79]: 0000 0000
DEBUG: UDP input: PRIES: byte[80,81,82,83]: 0000 584d
DEBUG: UDP input: PRIES: byte[84,85,86,87]: 5050 2043
DEBUG: UDP input: PRIES: byte[88,89,90,91]: 6c69 656e
DEBUG: UDP input: PRIES: byte[92,93,94,95]: 7400 0000
DEBUG: UDP input: PRIES: byte[96,97,98,99]: 0000 0000
DEBUG: UDP input: PRIES: byte[100,101,102,103]: 0000 0000
DEBUG: UDP input: PRIES: byte[104,105,106,107]: 0000 0000
DEBUG: UDP input: PRIES: byte[108,109,110,111]: 0000 0000
DEBUG: UDP input: PRIES: byte[112,113,114,115]: 0000 0000
DEBUG: UDP input: PRIES: byte[116,117,118,119]: 0000 0000
DEBUG: UDP input: PRIES: byte[120,121,122,123]: 0000 0000
DEBUG: UDP input: PRIES: byte[124,125,126,127]: 0000 0000
DEBUG: UDP input: PRIES: byte[128,129,130,131]: 0000 0000
DEBUG: UDP input: PRIES: byte[132,133,134,135]: 0000 0000
DEBUG: UDP input: PRIES: byte[136,137,138,139]: 0003 0303
DEBUG: UDP input: PRIES: byte[140,141,142,143]: 030d 0003
DEBUG: UDP input: PRIES: byte[144,145,146,147]: 0969 702d
DEBUG: UDP input: PRIES: byte[148,149,150,151]: 6361 6d65
DEBUG: UDP input: PRIES: byte[152,153,154,155]: 7261 0000
DEBUG: UDP input: PRIES: byte[156,157,158,159]: 0000 0000
DEBUG: UDP input: PRIES: byte[160,161,162,163]: 0000 0000
DEBUG: UDP input: PRIES: byte[164,165,166,167]: 0000 0000
DEBUG: UDP input: PRIES: byte[168,169,170,171]: 0049 5020
DEBUG: UDP input: PRIES: byte[172,173,174,175]: 5669 6465
DEBUG: UDP input: PRIES: byte[176,177,178,179]: 6f20 5375
DEBUG: UDP input: PRIES: byte[180,181,182,183]: 7276 6569
DEBUG: UDP input: PRIES: byte[184,185,186,187]: 6c6c 616e
DEBUG: UDP input: PRIES: byte[188,189,190,191]: 6365 2043
DEBUG: UDP input: PRIES: byte[192,193,194,195]: 616d 6572
DEBUG: UDP input: PRIES: byte[196,197,198,199]: 6100 0000
DEBUG: UDP input: PRIES: byte[200,201,202,203]: 0000 0000
DEBUG: UDP input: PRIES: byte[204,205,206,207]: 0000 0000
DEBUG: UDP input: PRIES: byte[208,209,210,211]: 0000 0000
DEBUG: UDP input: PRIES: byte[212,213,214,215]: 0000 0000
DEBUG: UDP input: PRIES: byte[216,217,218,219]: 0000 0000
DEBUG: UDP input: PRIES: byte[220,221,222,223]: 0000 0000
DEBUG: UDP input: PRIES: byte[224,225,226,227]: 0303 0303
DEBUG: UDP input: PRIES: byte[228,229,230,231]: 0d00 030a
DEBUG: UDP input: PRIES: byte[232,233,234,235]: 7375 7276
DEBUG: UDP input: PRIES: byte[236,237,238,239]: 6569 6c6c
DEBUG: UDP input: PRIES: byte[240,241,242,243]: 616e 6365
DEBUG: UDP input: PRIES: byte[244,245,246,247]: 2d64 6973
DEBUG: UDP input: PRIES: byte[248,249,250,251]: 7472 6962
DEBUG: UDP input: PRIES: byte[252,253,254,255]: 7574 696f
DEBUG: UDP input: PRIES: byte[256,257,258,259]: 5375 7276
DEBUG: UDP input: PRIES: byte[260,261,262,263]: 6569 6c6c
DEBUG: UDP input: PRIES: byte[264,265,266,267]: 616e 6365
DEBUG: UDP input: PRIES: byte[268,269,270,271]: 2044 6973
DEBUG: UDP input: PRIES: byte[272,273,274,275]: 7472 6962
DEBUG: UDP input: PRIES: byte[276,277,278,279]: 7574 696f
DEBUG: UDP input: PRIES: byte[280,281,282,283]: 6e00 0000
DEBUG: UDP input: PRIES: byte[284,285,286,287]: 0000 0000
DEBUG: UDP input: PRIES: byte[288,289,290,291]: 0000 0000
DEBUG: UDP input: PRIES: byte[292,293,294,295]: 0000 0000
DEBUG: UDP input: PRIES: byte[296,297,298,299]: 0000 0000
DEBUG: UDP input: PRIES: byte[300,301,302,303]: 0000 0000
DEBUG: UDP input: PRIES: byte[304,305,306,307]: 0000 0000
DEBUG: UDP input: PRIES: byte[308,309]: 0000
DEBUG: UDP input: PRIES: Message Version: 9
DEBUG: convert: PRIES: NETFLOW_V9 Conversion: sysUpTime=3977944382, unixSecs=1456027925, timeHeader=1452049980618
DEBUG: convert: PRIES: Template ID=1, Number Elements=4
DEBUG: convert: PRIES: Template ID=65335, Number Elements=257
DEBUG: convert: PRIES: Failure due to malicious flowset ID, len=130670
DEBUG: convert: PRIES: len=130670, templates.max=350, templates.cols=2
DEBUG: convert: Error at V9_OPT_TEMPLATE_SET_ID
WARNING: UDP input: Message conversion error; skipping message...

The code that prints the packet out for reference:

    /* receive packet */
    len = recvfrom(sock, *packet, BUFF_LEN, 0, (struct sockaddr*) &address, &addr_len);
    ssize_t jplen = len;

...
    ssize_t k = 0;
    MSG_DEBUG(msg_module, "PRIES: RECEIVED Packet: length=%zd", jplen);
    while (k<jplen) {
        if (k+4 < jplen) {
          MSG_DEBUG(msg_module, "PRIES: byte[%zd,%zd,%zd,%zd]: %02x%02x %02x%02x", k, k+1, k+2, k+3,
                                  ((const unsigned char *) *packet)[k],
                                  ((const unsigned char *) *packet)[k+1],
                                  ((const unsigned char *) *packet)[k+2],
                                  ((const unsigned char *) *packet)[k+3]);
        } else if (k+3 < jplen) {
          MSG_DEBUG(msg_module, "PRIES: byte[%zd,%zd,%zd]: %02x%02x %02x", k, k+1, k+2,
                                  ((const unsigned char *) *packet)[k],
                                  ((const unsigned char *) *packet)[k+1],
                                  ((const unsigned char *) *packet)[k+2]);
        } else if (k+2 < jplen) {
          MSG_DEBUG(msg_module, "PRIES: byte[%zd,%zd]: %02x%02x", k, k+1,
                                  ((const unsigned char *) *packet)[k],
                                  ((const unsigned char *) *packet)[k+1]);
        } else {
          MSG_DEBUG(msg_module, "byte:[%zd]: %02x ", k, ((const unsigned char *) *packet)[k]);
        }
        k=k+4;
    }

I'm a c++ novice, please forgive any weirdness above ;)

jepries commented 8 years ago

Tacking closer. When the options template doesn't have time entries, we are off by 2 bytes in the conversion...

DEBUG: convert: PRIES: NETFLOW_V9 Conversion: sysUpTime=4017843392,   unixSecs=1456067821, timeHeader=1452049977608
DEBUG: convert: PRIES: Processing Template Set, len=22
DEBUG: convert: PRIES: byte[0,1,2,3]: 0003 001a
DEBUG: convert: PRIES: byte[4,5,6,7]: 0101 0004
DEBUG: convert: PRIES: byte[8,9,10,11]: 000c 0001
DEBUG: convert: PRIES: byte[12,13,14,15]: 0004 005f
DEBUG: convert: PRIES: byte[16,17,18,19]: 0004 0060
DEBUG: convert: PRIES: byte[20,21]: 0018
DEBUG: convert: PRIES: tmp=32, templSet+len=54
DEBUG: convert: PRIES: Template ID=1, Number Elements=4
DEBUG: convert: PRIES: tmp=52, templSet+len=54
DEBUG: convert: PRIES: Template ID=65335, Number Elements=257
DEBUG: convert: PRIES: Failure due to malicious flowset ID, len=130670
DEBUG: convert: PRIES: len=130670, templates.max=50, templates.cols=2
DEBUG: convert: Error at V9_OPT_TEMPLATE_SET_ID

There is only 1 template incoming to the insert_timestamp_template and the len is just slightly off when no timestamps found.....

jepries commented 8 years ago

I don't know if I'm bugging you guys or not, just adding data here as I track this down.

Here is what a normal template set processing looks like with the insert_timestamp_template method:'

DEBUG: convert: PRIES: Processing Template Set, len=48
DEBUG: convert: PRIES: byte[0,1,2,3]: 0002 0034
DEBUG: convert: PRIES: byte[4,5,6,7]: 0101 000b
DEBUG: convert: PRIES: byte[8,9,10,11]: 0167 0008
DEBUG: convert: PRIES: byte[12,13,14,15]: 90ec 0004
DEBUG: convert: PRIES: byte[16,17,18,19]: 90eb 0004
DEBUG: convert: PRIES: byte[20,21,22,23]: 90f4 0004
DEBUG: convert: PRIES: byte[24,25,26,27]: 90f2 0004
DEBUG: convert: PRIES: byte[28,29,30,31]: 00eb 0004
DEBUG: convert: PRIES: byte[32,33,34,35]: 9858 0004
DEBUG: convert: PRIES: byte[36,37,38,39]: 000e 0004
DEBUG: convert: PRIES: byte[40,41,42,43]: 90fe 0004
DEBUG: convert: PRIES: byte[44,45,46,47]: 0053 0008
DEBUG: convert: PRIES: tmp=208, templSet+len=256
DEBUG: convert: PRIES: Template ID=1, Number Elements=11
DEBUG: convert: PRIES: tmp incremented, now tmp=216
DEBUG: convert: PRIES: no start/end found, tmp->length=8
DEBUG: convert: PRIES: tmp incremented, now tmp=220
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=224
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=228
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=232
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=236
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=240
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=244
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=248
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=252
DEBUG: convert: PRIES: no start/end found, tmp->length=8
DEBUG: convert: PRIES: tmp incremented, now tmp=0
DEBUG: convert: PRIES: no start/end found, tmp->length=1
DEBUG: ipfix_message: [0] Processing data
INFO: preprocessor: [0] New template ID 257

Nice and pretty.

Here is what an Options template looks like, not sure I understand it yet:

DEBUG: convert: PRIES: Processing Template Set, len=22
DEBUG: convert: PRIES: byte[0,1,2,3]: 0003 001a
DEBUG: convert: PRIES: byte[4,5,6,7]: 0101 0004
DEBUG: convert: PRIES: byte[8,9,10,11]: 000c 0001
DEBUG: convert: PRIES: byte[12,13,14,15]: 0004 005f
DEBUG: convert: PRIES: byte[16,17,18,19]: 0004 0060
DEBUG: convert: PRIES: byte[20,21]: 0018
DEBUG: convert: PRIES: tmp=80, templSet+len=102
DEBUG: convert: PRIES: Template ID=1, Number Elements=4
DEBUG: convert: PRIES: tmp incremented, now tmp=88
DEBUG: convert: PRIES: no start/end found, tmp->length=1
DEBUG: convert: PRIES: tmp incremented, now tmp=92
DEBUG: convert: PRIES: no start/end found, tmp->length=95
DEBUG: convert: PRIES: tmp incremented, now tmp=96
DEBUG: convert: PRIES: no start/end found, tmp->length=96
DEBUG: convert: PRIES: tmp incremented, now tmp=100
DEBUG: convert: PRIES: no start/end found, tmp->length=94
DEBUG: convert: PRIES: tmp=100, templSet+len=102
DEBUG: convert: PRIES: Template ID=65335, Number Elements=257
DEBUG: convert: PRIES: Failure due to malicious flowset ID, len=130670
DEBUG: convert: PRIES: len=130670, templates.max=50, templates.cols=2
DEBUG: convert: Error at V9_OPT_TEMPLATE_SET_ID
WARNING: UDP input: Message conversion error; skipping message...

Note, there are a couple bugs in my output's, I'm missing the last 2 bytes above..... and ovflowing the uint8_t on tmp, but you get the gist...

jepries commented 8 years ago

I see the problem I think.

An Options template has an extra 2 bytes than a normal Template in v9!

options template

FlowSet ID = 1
Length
Template ID
Option Scope Length <== EXTRA 2 BYTES
Option Length
Scope Field 1 Type
Scope Field 1 Length
. 
.
Scope Field N Length
Option Field 1 Type
Option Field 1 Length

Template

FlowSet ID = 0
Length
Template ID
Field Count
Field 1 Type
Field 1 Length
Field 2 Type  
Field 2 Length
.
.
.
Field N Type
Field N Length

I think the options template requires a different method to account for that extra field?

thorgrin commented 8 years ago

Thanks for narroving this down. Do you have any data sample on which we can reproduce this? I'm quite sure that we did not test option template conversion, so this sure seems to be the right thing to check.

jepries commented 8 years ago

@thorgrin Thanks for responding.... I'm writing the insert_timestamp_otemplate now and it almost works, but I'm a hack so I know I'm doing it badly. I've gotten it almost working but after processing an options template it runs into an endless loop gobbling 100% cpu.

I put too much code into it, I noticed there is more work back in the method calling insert_timestamp....

I'll clean it up to as far as I can get it. In the mean time, how would I capture sample data for you? I'd love to send it to you.

jepries commented 8 years ago

Here are some log messages of v9 options templates incoming, it shows the data. Also is the code that process it and then downstream errors concerning my hacking it through :).

Here is the additional method that I call instead of the traditional insert_timestamp_template method, call it in the convert method for Options templates:

/* \brief Inserts 64b timestamps into NetFlow v9 OPTIONS template
 *
 * Finds original timestamps (field ID 21 and 22) and replaces them with field ID 152 and 153
 *
 * \param templSet pointer to Template Set
 */
int insert_timestamp_otemplate(struct ipfix_set_header *templSet)
{
    struct ipfix_set_header *tmp;
    uint16_t len, num, i, id, k, scopeLen, optLen;

    tmp = templSet;

    /* Get template set total length without set header length */
    len = ntohs(tmp->length) - 4;

    MSG_DEBUG(msg_module, "PRIES: Processing Options Template Set minus Header, len=%u", len);
    while (k<len+4) {
    if (k+4 <= len+4) {
      MSG_DEBUG(msg_module, "PRIES: byte[%u,%u,%u,%u]: %02x%02x %02x%02x", k, k+1, k+2, k+3,
                              ((const unsigned char *) templSet)[k],
                              ((const unsigned char *) templSet)[k+1],
                              ((const unsigned char *) templSet)[k+2],
                              ((const unsigned char *) templSet)[k+3]);
    } else if (k+3 <= len+4) {
      MSG_DEBUG(msg_module, "PRIES: byte[%u,%u,%u]: %02x%02x %02x", k, k+1, k+2,
                              ((const unsigned char *) templSet)[k],
                              ((const unsigned char *) templSet)[k+1],
                              ((const unsigned char *) templSet)[k+2]);
    } else if (k+2 <= len+4) {
      MSG_DEBUG(msg_module, "PRIES: byte[%u,%u]: %02x%02x", k, k+1,
                              ((const unsigned char *) templSet)[k],
                              ((const unsigned char *) templSet)[k+1]);
    } else {
      MSG_DEBUG(msg_module, "PRIES: byte:[%u]: %02x ", k, ((const unsigned char *) templSet)[k]);
    }
    k=k+4;
    }
    /* Iterate through all templates */
    while ((uint8_t *) tmp < (uint8_t *) templSet + len) {
      MSG_DEBUG(msg_module, "PRIES: tmp=%u, OptTemplSet+len=%u", (uint8_t)tmp, (uint8_t)templSet+len);
            tmp++; //We are now pointing 4 bytes in, this is an Options template, it has 3 items to get
                   //Flow set ID
                   //Options Scope Length in bytes
                   //Options Length in bytes
                   //  -This deviates from the 2 element ipfix_set_header type
                   //  - so we are going to hack out a solution here.
                   //  - the number of "pairs" of "ipfix_set_header" is (scope_length + options_length) divided by 4

            /* Get template ID and number of elements */
            /* here is the hack, we are going to recast the current location of tmp as
               a ipfix_options_template_record and get what we need. */
            struct ipfix_options_template_record *tmp2;
            tmp2 = tmp;
            id = ntohs(tmp2->template_id) - IPFIX_MIN_RECORD_FLOWSET_ID;
            scopeLen = ntohs(tmp2->count);
            optLen = ntohs(tmp2->scope_field_count);
            num = (scopeLen + optLen) / 4;

            //ANOTHER GLARING DIFFERENCE between NFv9 and IPFIX Options templates is that
            //  v9 maintains scopeLen and optLen in bytes!!!! Wheras IPFIX has them in "count".
            //  argh.... So we need to conver them.

            //Field Count
            //
            //Number of all fields in this Options Template Record, including
            //the Scope Fields.
            //
            //Scope Field Count
            //
            //Number of scope fields in this Options Template Record.  The Scope
            //Fields are normal Fields, except that they are interpreted as
            //scope at the Collector.  A scope field count of N specifies that
            //the first N Field Specifiers in the Template Record are Scope
            //Fields.  The Scope Field Count MUST NOT be zero.
            //
            //  NOTE, I believe this is handled back in the convert method.

            //MSG_DEBUG(msg_module, "PRIES: OptTemplate ID=%u, ScopeLength=%u, OptLength=%u, Number Elements=%u", id, scopeLen, optLen, num);
            //tmp2->count = htons( num );
            //MSG_DEBUG(msg_module, "PRIES: setting IPFIX Field Count to %u, htons:%u", num, htons(num));
            //tmp2->scope_field_count = htons(optLen/4);
            //MSG_DEBUG(msg_module, "PRIES: setting IPFIX Scope Field Count to %u, htons:%u", optLen/4, htons(optLen/4));

            //NOW THE HACK, I have to get tmp to point 6 bytes up, not 4.
            //how do I do that...
            //if i increment tmp2, it contans that data element so we pass where I want to be.
            //if i increment tmp, it goes 4 bytes up, I only want it to go 2.
            //wonder if i can recast curent location of tmp2 to an uint16_t and increment it, then set tmp to it?
            uint16_t *tmp3 = tmp2;
            tmp3++;
            tmp=tmp3;

            /* JEP */
            if (id >= templates.max) {
                    templates.max += 20;
                    templates.templ = realloc(templates.templ, templates.max * templates.cols * sizeof(int));

                    if (templates.templ == NULL) {
                            /* JEP */
                            MSG_DEBUG(msg_module, "PRIES: Failure to allocate templates.templ");
                            return 1;
                    }

                    unsigned int i;
                    for (i = (templates.max - 20) * templates.cols; i < templates.max * templates.cols; i++) {
                            templates.templ[i] = 0;
                    }
            }

            uint32_t len = templates.cols * id;
            uint32_t pos = len + 1;

            /* Input check: avoid overflow due to malicious flowset IDs */
            if (len > templates.max * templates.cols) {
                    /* JEP */
                    MSG_DEBUG(msg_module, "PRIES: Failure due to malicious flowset ID, len=%lu", len);
                    MSG_DEBUG(msg_module, "PRIES: len=%lu, templates.max=%lu, templates.cols=%lu", len, templates.max, templates.cols);
                    return 1;
            }

            /* Set default values for length and timestamp position */
            templates.templ[len] = 0;
            templates.templ[pos] = -1;

            /* Iterate through all elements */
            for (i = 0; i < num; i++) {
                    tmp++;
                    MSG_DEBUG(msg_module,"PRIES: tmp incremented, now tmp=%u", (uint8_t)tmp);
                    /* We are looking for timestamps - elements with id 21 (end) and 22 (start) */
                    if (ntohs(tmp->flowset_id) == NETFLOW_V9_END_ELEM) {
                            /* We don't know which one comes first so we need to check it */
                            if (templates.templ[pos] == -1) {
                                    templates.templ[pos] = templates.templ[len];
                            }

                            /* Change element ID and element length (32b -> 64b) */
                            tmp->flowset_id = htons(FLOW_END);
                            tmp->length = htons(BYTES_8);
                            templates.templ[len] += BYTES_4;
                    } else if (ntohs(tmp->flowset_id) == NETFLOW_V9_START_ELEM) {
                            /* Do the same thing for element 22 */
                            if (templates.templ[pos] == -1) {
                                    templates.templ[pos] = templates.templ[len];
                            }

                            tmp->flowset_id = htons(FLOW_START);
                            tmp->length = htons(BYTES_8);
                            templates.templ[len] += BYTES_4;
                    } else {
                            templates.templ[len] += ntohs(tmp->length);
                            MSG_DEBUG(msg_module, "PRIES: no start/end found, tmp->length=%lu", ntohs(tmp->length));
                    }
            }
    }

    return 0;
}

Here is the debug trace including my wonderful segmentation fault

DEBUG: convert: PRIES: Processing Options Template Set minus Header, len=22
DEBUG: convert: PRIES: byte[0,1,2,3]: 0003 001a
DEBUG: convert: PRIES: byte[4,5,6,7]: 0101 0004
DEBUG: convert: PRIES: byte[8,9,10,11]: 000c 0001
DEBUG: convert: PRIES: byte[12,13,14,15]: 0004 005f
DEBUG: convert: PRIES: byte[16,17,18,19]: 0004 0060
DEBUG: convert: PRIES: byte[20,21,22,23]: 0018 005e
DEBUG: convert: PRIES: byte[24,25]: 0037
DEBUG: convert: PRIES: tmp=176, OptTemplSet+len=198
DEBUG: convert: PRIES: tmp incremented, now tmp=186
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=190
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=194
DEBUG: convert: PRIES: no start/end found, tmp->length=24
DEBUG: convert: PRIES: tmp incremented, now tmp=198
DEBUG: convert: PRIES: no start/end found, tmp->length=55
DEBUG: ipfix_message: [0] Processing data
INFO: preprocessor: [0] New options template ID 257
DEBUG: preprocessor: [0] Options template ID 258 already exists; rewriting...
WARNING: template manager: [0] Template 257 is malformed (bad template count); skipping...
WARNING: preprocessor: [0] Cannot parse options template set; skipping to next set...
WARNING: preprocessor: [0] Data template with ID 771 not found
DEBUG: convert: PRIES: Processing Options Template Set minus Header, len=22
DEBUG: convert: PRIES: byte[0,1,2,3]: 0003 001a
DEBUG: convert: PRIES: byte[4,5,6,7]: 0101 0004
DEBUG: convert: PRIES: byte[8,9,10,11]: 000c 0001
DEBUG: convert: PRIES: byte[12,13,14,15]: 0004 005f
DEBUG: convert: PRIES: byte[16,17,18,19]: 0004 0060
DEBUG: convert: PRIES: byte[20,21,22,23]: 0018 005e
DEBUG: convert: PRIES: byte[24,25]: 0037
DEBUG: convert: PRIES: tmp=224, OptTemplSet+len=246
DEBUG: convert: PRIES: tmp incremented, now tmp=234
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=238
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=242
DEBUG: convert: PRIES: no start/end found, tmp->length=24
DEBUG: convert: PRIES: tmp incremented, now tmp=246
DEBUG: convert: PRIES: no start/end found, tmp->length=55
DEBUG: dummy Intermediate Process: got IPFIX message!
DEBUG: ipfix_message: [0] Processing data
DEBUG: preprocessor: [0] Options template ID 258 already exists; rewriting...
DEBUG: template manager: [0] Received the same template as last time, not replacing
DEBUG: preprocessor: [0] Options template ID 258 already exists; rewriting...
WARNING: template manager: [0] Template 257 is malformed (bad template count); skipping...
WARNING: preprocessor: [0] Cannot parse options template set; skipping to next set...
WARNING: preprocessor: [0] Data template with ID 771 not found
DEBUG: dummy Intermediate Process: got IPFIX message!
DEBUG: convert: PRIES: Processing Options Template Set minus Header, len=22
DEBUG: convert: PRIES: byte[0,1,2,3]: 0003 001a
DEBUG: convert: PRIES: byte[4,5,6,7]: 0101 0004
DEBUG: convert: PRIES: byte[8,9,10,11]: 000c 0001
DEBUG: convert: PRIES: byte[12,13,14,15]: 0004 005f
DEBUG: convert: PRIES: byte[16,17,18,19]: 0004 0060
DEBUG: convert: PRIES: byte[20,21,22,23]: 0018 005e
DEBUG: convert: PRIES: byte[24,25]: 0037
DEBUG: convert: PRIES: tmp=0, OptTemplSet+len=22
DEBUG: convert: PRIES: tmp incremented, now tmp=10
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=14
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=18
DEBUG: convert: PRIES: no start/end found, tmp->length=24
DEBUG: convert: PRIES: tmp incremented, now tmp=22
DEBUG: convert: PRIES: no start/end found, tmp->length=55
DEBUG: convert: ERROR at Sanity Check, set_len: 30066 > len: 1361
WARNING: UDP input: Message conversion error; skipping message...
DEBUG: convert: PRIES: Processing Options Template Set minus Header, len=22
DEBUG: convert: PRIES: byte[0,1,2,3]: 0003 001a
DEBUG: convert: PRIES: byte[4,5,6,7]: 0101 0004
DEBUG: convert: PRIES: byte[8,9,10,11]: 000c 0001
DEBUG: convert: PRIES: byte[12,13,14,15]: 0004 005f
DEBUG: convert: PRIES: byte[16,17,18,19]: 0004 0060
DEBUG: convert: PRIES: byte[20,21,22,23]: 0018 005e
DEBUG: convert: PRIES: byte[24,25]: 0037
DEBUG: convert: PRIES: tmp=224, OptTemplSet+len=246
DEBUG: convert: PRIES: tmp incremented, now tmp=234
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=238
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=242
DEBUG: convert: PRIES: no start/end found, tmp->length=24
DEBUG: convert: PRIES: tmp incremented, now tmp=246
DEBUG: convert: PRIES: no start/end found, tmp->length=55
DEBUG: ipfix_message: [0] Processing data
DEBUG: preprocessor: [0] Options template ID 258 already exists; rewriting...
DEBUG: template manager: [0] Received the same template as last time, not replacing
DEBUG: dummy Intermediate Process: got IPFIX message!
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: convert: PRIES: Processing Options Template Set minus Header, len=22
DEBUG: convert: PRIES: byte[0,1,2,3]: 0003 001a
DEBUG: convert: PRIES: byte[4,5,6,7]: 0101 0004
DEBUG: convert: PRIES: byte[8,9,10,11]: 000c 0001
DEBUG: convert: PRIES: byte[12,13,14,15]: 0004 005f
DEBUG: convert: PRIES: byte[16,17,18,19]: 0004 0060
DEBUG: convert: PRIES: byte[20,21,22,23]: 0018 005e
DEBUG: convert: PRIES: byte[24,25]: 0037
DEBUG: convert: PRIES: tmp=96, OptTemplSet+len=118
DEBUG: convert: PRIES: tmp incremented, now tmp=106
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=110
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=114
DEBUG: convert: PRIES: no start/end found, tmp->length=24
DEBUG: convert: PRIES: tmp incremented, now tmp=118
DEBUG: convert: PRIES: no start/end found, tmp->length=55
DEBUG: ipfix_message: [0] Processing data
DEBUG: preprocessor: [0] Options template ID 258 already exists; rewriting...
DEBUG: template manager: [0] Received the same template as last time, not replacing
DEBUG: convert: PRIES: Processing Options Template Set minus Header, len=22
DEBUG: dummy Intermediate Process: got IPFIX message!
DEBUG: convert: PRIES: byte[0,1,2,3]: 0003 001a
DEBUG: convert: PRIES: byte[4,5,6,7]: 0101 0004
DEBUG: convert: PRIES: byte[8,9,10,11]: 000c 0001
DEBUG: convert: PRIES: byte[12,13,14,15]: 0004 005f
DEBUG: convert: PRIES: byte[16,17,18,19]: 0004 0060
DEBUG: convert: PRIES: byte[20,21,22,23]: 0018 005e
DEBUG: convert: PRIES: byte[24,25]: 0037
DEBUG: convert: PRIES: tmp=224, OptTemplSet+len=246
DEBUG: convert: PRIES: tmp incremented, now tmp=234
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=238
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=242
DEBUG: convert: PRIES: no start/end found, tmp->length=24
DEBUG: convert: PRIES: tmp incremented, now tmp=246
DEBUG: convert: PRIES: no start/end found, tmp->length=55
DEBUG: ipfix_message: [0] Processing data
DEBUG: preprocessor: [0] Options template ID 258 already exists; rewriting...
DEBUG: template manager: [0] Received the same template as last time, not replacing
DEBUG: preprocessor: [0] Options template ID 258 already exists; rewriting...
WARNING: template manager: [0] Template 257 is malformed (bad template count); skipping...
WARNING: preprocessor: [0] Cannot parse options template set; skipping to next set...
WARNING: preprocessor: [0] Data template with ID 771 not found
DEBUG: dummy Intermediate Process: got IPFIX message!
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: json_storage: Unknown element (e0id95)
DEBUG: json_storage: Unknown element (e0id94)
DEBUG: convert: PRIES: Processing Options Template Set minus Header, len=22
DEBUG: convert: PRIES: byte[0,1,2,3]: 0003 001a
DEBUG: convert: PRIES: byte[4,5,6,7]: 0100 0004
DEBUG: convert: PRIES: byte[8,9,10,11]: 000c 0001
DEBUG: convert: PRIES: byte[12,13,14,15]: 0004 000a
DEBUG: convert: PRIES: byte[16,17,18,19]: 0004 0052
DEBUG: convert: PRIES: byte[20,21,22,23]: 0020 0053
DEBUG: convert: PRIES: byte[24,25]: 0040
DEBUG: convert: PRIES: tmp=176, OptTemplSet+len=198
DEBUG: convert: PRIES: tmp incremented, now tmp=186
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=190
DEBUG: convert: PRIES: no start/end found, tmp->length=4
DEBUG: convert: PRIES: tmp incremented, now tmp=194
DEBUG: convert: PRIES: no start/end found, tmp->length=32
DEBUG: convert: PRIES: tmp incremented, now tmp=198
DEBUG: convert: PRIES: no start/end found, tmp->length=64
Segmentation fault (core dumped)

thorgrin commented 8 years ago

How do you feed the data to IPFIXcol? If it comes from network, you can use tcpdump to save a pcap with a sample. Be sure to start tcpdump before the export so that the templates are captured.

I'll test your code with the data, I'm not able to reproduce it without the option templates and I have no means to export them.

jepries commented 8 years ago

Will do. It takes about 10 minutes for all the templates to come in, I'll capture enough to make sure you have them. Data is streaming from lab routers continuously.

jepries commented 8 years ago

@thorgrin Petr, thanks for taking a look at this. We are trying to capture PfR product exported from Cisco and this tool is oh so close to being able to do that!

Attached is 30 minutes of capture, within that you should have received 890 packets and the NFv9 options templates exported about 5 to 6 times. (every 5 minutes). Mixed in are other exports for data, those work great. The exports are from lab routers, I think the target client addresses specified by the exporters is 19.19.19.19 (my VM running inside the lab). I don't have visibility to the exporters yet, but can get what the exporting templates look like soon if need be.

Within this zip file along with the capture is

startup parameters in startup_params.txt,
the internalcfg and the elements.xml changed to handle the NFv9 elements we have found so far (plus modified the standard IPFIX elements to match the exported names published by the PfR product).
I've included the startup.xml as well just in case that helps.

Let me know if what is in here is OK. Thanks again! PfR_Capture.zip

thorgrin commented 8 years ago

@jepries I've successfully replayed the data to the collector using second machine and a little tcprewrite+tcpreplay magic.

I've found several potential problems with the conversion code. You could try to:

disable inserting the timestamps altogether
send only one source at the time (I'm not sure whether the same template IDs do not clash)

Meanwhile we will try to collect more data samples and fix the conversion properly. It might take some time but it seems better than to hotfix the current code.

jepries commented 8 years ago

I think I see the problem. Line 644 of convert.c, you are looking for enterprise ID's in a NFv9 template. The ID's incoming from the PfR Export we know have ID's > 32768 which would be artificially setting the enterprise bit. This then corrupts the template as the counts go wonky. I don't believe NFv9 (according to http://www.cisco.com/en/US/technologies/tk648/tk362/technologies_white_paper09186a00800a3db9.pdf) contains enterprise ID's in options templates. I will try bypassing this logic, but I think we are going to have to add the logic you have to remap those large element id's and insert the all 1's enterprise id?

I'll work on it this weekend (only time I get to play with this) and see if I can fix it.

thorgrin commented 8 years ago

The function unpack_enterprise_elements called at line 616 should take care of enterprise elements. However, it is entirely possible that the function works only for Data templates and not for option templates. This might be worth looking into

jepries commented 8 years ago

Thanks Petr had that same thought, I'll create a unpack_enterprise method for otemplates and do the 2 byte move over the extra count field.

jepries commented 8 years ago

@thorgrin Petr, I believe I've hotfixed convert.c to accept the incoming options templates that I sent you in the tcpdump. The file is attached. I apologize for not following your coding standards closely, I was coding in VI on the targeted VM (just easier) that was collecting the messages. Please take a look and make it better :).

-- see convert.c in next post

jepries commented 8 years ago

that last convert.c i posted had a glaring error, i've cleaned it up and removed some debug statements, it is here. I tried to push a new branch up called NFv9_PfR but don't have permissions. I've modified convert.c and json/Storage.cpp to handle the PfR product export, seems to work, may have more tweaking to do but at least i'm at the point now where downstream customers can evaluate the data.

ps, the copying of convert.c attached here has been cleaned up to meet your coding standards. I know there is dumb stuff i'm doing in there but it works. Would appreciate you cleaning it up and making it more efficient.

convert.c.txt Storage.cpp.txt

thorgrin commented 8 years ago

I've taken your convert.c and incorporated the changes to devel branch. The functions you added are almost exact copies of existing ones, but for option templates. It works, sort of, however, there are some invalid memory accesses during the conversion. Since we really want to rework this from scratch, I do not want to spend too much time on it. I hope that it works for you, feel free to send any more patches.

CESNET / ipfixcol

Data records for options templates (converted from NFv9) do not increase sequence number #118