Forum Discussion

Log4j2's avatar
Log4j2
Icon for Altocumulus rankAltocumulus
May 10, 2022
Solved

iRule [string range...] not chunking data properly

I have an irule (much of which I found here) that is to gather some much needed troubleshooting data I need in regards to the headers and payload I have coming in.  The payload is obvisouly too large for a single log line so this was supposed to chunk it into manageable bytes.

I had to make some modifications to the original irule which did not work, but now it is working, sort of.  It logs the first 900 bytes as it should, then something happens and skips a bunch, and then logs the final bytes of data.

I can't understand why it's not grabbing either the proper amount of data or failing to output this second chunk of missing data before making its final loop.

iRule is here:

 

 

when RULE_INIT {

    # Log debug to /var/log/ltm? 1=yes, 0=no
    set static::payload_dbg 1

    # Limit payload collection to 5Mb
    set static::max_collect_len 5368709

    # Max characters to log locally (must be less than 1024 bytes)
    # https://clouddocs.f5.com/api/irules/log.html
    set static::max_chars 900
    
    set static::min_chars 0
}
when HTTP_REQUEST {

    # Only collect POST request payloads
    if {[HTTP::method] equals "POST"}{

        if {$static::payload_dbg}{log local0. "POST request"}

        # Get the content length so we can request the data to be processed in the HTTP_REQUEST_DATA event.
        if {[HTTP::header exists "Content-Length"]}{
            set content_length [HTTP::header "Content-Length"]
        } else {
            set content_length 0
        }
        # content_length of 0 indicates chunked data (of unknown size)
        if {$content_length > 0 && $content_length < $static::max_collect_len}{
            set collect_length $content_length
        } else {
            set collect_length $static::max_collect_len
        }
        if {$static::payload_dbg}{log local0. "Content-Length: $content_length, Collect length: $collect_length"}
        
        foreach aHeader [HTTP::header names] {
        
        log local0. "HTTP Request Headers: $aHeader: [HTTP::header value $aHeader]"
        
        }
        
        #set payload [HTTP::collect $collect_length]
        HTTP::collect $collect_length
    }
}

when HTTP_REQUEST_DATA {

    # Log the bytes collected
    if {$static::payload_dbg}{log local0. "Collected [HTTP::payload length] bytes"}

    # Log the payload locally
    if {[HTTP::payload length] < $static::max_chars}{
        log local0. "Payload=[HTTP::payload]"
    } else {
        # Initialize variables
        set remaining [HTTP::payload]
        set position 0
        set count 1
        set bytes_logged 0

        # Loop through and log each chunk of the payload
        while {[string length $remaining] > $static::min_chars}{
        
            #chunk = 899
            set chunk [expr {$position + $static::max_chars -1}]
            
            log local0. "Chunk: $chunk"
            log local0. "Position start: $position"

            # Get the current chunk to log (subtract 1 from the end as string range is 0 indexed)
            set current [string range $remaining $position $chunk]
            log local0. "chunk $count=$current"
            log local0. "Current chunks bytes: [string length $current]"

            # Add the length of the current chunk to the position for the next chunk
            incr position [string length $current]

            # Get the next chunk to log
            set remaining [string range $remaining $position end]
            incr count
            incr bytes_logged $position
            log local0. "remaining bytes=[string length $remaining], \$position=$position, \$count=$count, \$bytes_logged=$bytes_logged"
        }
        
        if {[string length $remaining]}{
            log local0. "chunk $count=$current"
            incr bytes_logged [string length $remaining]
        }
        
        log local0. "Logged $count chunks for a total of $bytes_logged bytes"
    }
}

when HTTP_RESPONSE {

    foreach aHeader [HTTP::header names] {
    log local0. "HTTP Request Headers: $aHeader: [HTTP::header value $aHeader]"
    }
}

 

 

The image below shows what I'm talking about - it even says "Oh I found 3 chunks", but I'm only being presented 2.

I added some logging around the position, chunk value (aka end position), and bytes logged to help illustrate that it's clearly skipping over something.

Any help would be appreciated!

Thanks

  • In fact I have just grabbed this from an iRule i recently wrote. Almost the same, with fixed values. Note the end is 99 but the increment is 100. As you say, string range is zero-indexed

    for {set start 0; set end 99} {$start < [HTTP::payload length]} {incr start 100;incr end 100} {
                log local0.debug "[string range [HTTP::payload] $start $end ]"
            }

6 Replies

  • This sounds like the limit "900" that is set in the static variable because of F5 limit "The syslog facility is limited to logging 1024 bytes per request. Longer strings will be truncated."  . You may increase the limit static:max_chars to 1024 as each character is 8 bits (1 Byte) and it seems to me that this is your issue and also try using HSL remote logging to your syslog server or SIEM like splunk/elk/qradar etc. without logging locally as then maybe the limit of 1024 will not apply.

     

     

    https://clouddocs.f5.com/api/irules/log.html

    Also you play a little with the F5 HTTP profile and the chrunking to see if it helps changing it to the different modes:

    https://support.f5.com/csp/article/K5379

     

    • Log4j2's avatar
      Log4j2
      Icon for Altocumulus rankAltocumulus

      So I increased the max_char value to 1024 but I'm still getting the same issue, just more data in the first chunk.

      This time I've splatted the response to properly represent how many characters I'm actually getting back:

      chunk1
      
      xxxx_xxx=<xxxxxxxxxxx> <xxxxxxx>xxxx_xxxxxx</xxxxxxx> <xxxxxxx>xxxx://xxxx_xxx</xxxxxxx> <xxxxxxxxxxxxxxxxxxxx>x2xx37xx-0x94-4xx4-x70x-3xx74xx1x075</xxxxxxxxxxxxxxxxxxxx> <xxxxxxx>1.7</xxxxxxx> <xxxxxxxxxxxxxx>${xxxxxxxxxxxxxx}</xxxxxxxxxxxxxx> <xxxxxxxxxxx>100</xxxxxxxxxxx> <xxxxxxxxxx>100x</xxxxxxxxxx> <xxxxxxxxxxxxxx>12345678</xxxxxxxxxxxxxx> <xxxxxxxxxxxxxxx>x</xxxxxxxxxxxxxxx> <xxxxxxxxxxx>xxxx xxxxxxxxxxxx x - xxxx_xxxxxx-91</xxxxxxxxxxx> <xxxxxx>69420</xxxxxx> <xxxxxxxxxxxx>840</xxxxxxxxxxxx> <xxxxxxxxxx>4000000000001000</xxxxxxxxxx> <xxxxxxxxxxxx>01</xxxxxxxxxxxx> <xxxxxxxxxxx>2021</xxxxxxxxxxx> <xxxxxxxxxxxxxxxx>xxxx</xxxxxxxxxxxxxxxx> <xxxxxxxxxxxxxxxxx>x</xxxxxxxxxxxxxxxxx> <xxxxxxxxxxxxxxx>xxx</xxxxxxxxxxxxxxx> <xxxxxxxxxxxxxx1>1600 xxxxxxxxxxxx xxxx.</xxxxxxxxxxxxxx1> <xxxxxxxxxxxxxx2/> <xxxxxxxxxxxx>555-8675-309</xxxxxxxxxxxx> <xxxxxxxxxxx>xx
      chunk2
      
      xxxx/3.1</xxxxxxxxx> <xxxxxxxxxxxxx>xxxx/xxxx,xxxxxxxxxxx/xxxxx+xxx,xxxxxxxxxxx/xxx;x=0.9</xxxxxxxxxxxxx> <xxxxxxxxxxxxx>xxx</xxxxxxxxxxxxx> //<xxxxxxxxxx>01</xxxxxxxxxx> <xxxxxxxxxxxxxxxxxxxxxxxx>03</xxxxxxxxxxxxxxxxxxxxxxxx> <xxxxxxxxxxxxxxxxxxx>01,02</xxxxxxxxxxxxxxxxxxx> <xxxxxxxx>xxx64xxx-x19x-4728-8849-x3x50xxxxx39</xxxxxxxx> <xxxxxxxxxxxxx>${xxxxxxxxxxx}</xxxxxxxxxxxxx> <xxxxxxxxxxx>12341234</xxxxxxxxxxx> <xxxxxxxxxxxxx>xxxxxxxx</xxxxxxxxxxxxx> </xxxxxxxxxxx>

       

      My original request is like so:

      xxxx_xxx=<xxxxxxxxxxx>
      	<xxxxxxx>xxxx_xxxxxx</xxxxxxx>
      	<xxxxxxx>xxxx://xxxx_xxx</xxxxxxx>
      	<xxxxxxxxxxxxxxxxxxxx>${xxxxxxxxxxxxxxxxxxxx}</xxxxxxxxxxxxxxxxxxxx>
      	<xxxxxxx>1.7</xxxxxxx>
      	<xxxxxxxxxxxxxx>${xxxxxxxxxxxxxx}</xxxxxxxxxxxxxx>
      	<xxxxxxxxxxx>${xxxxxxxxxxx}</xxxxxxxxxxx>
      	<xxxxxxxxxx>${3xx-xxx-xxxxxxxxxx}</xxxxxxxxxx>
      	<xxxxxxxxxxxxxx>${xxxxxxxxxxx}</xxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxx>x</xxxxxxxxxxxxxxx>
      	<xxxxxxxxxxx>${__xxxxxxxxxxx()}-${__xxxxxx(0,99)}</xxxxxxxxxxx>
      	<xxxxxx>69420</xxxxxx>
      	<xxxxxxxxxxxx>840</xxxxxxxxxxxx>
      	<xxxxxxxxxx>1234567891012345</xxxxxxxxxx>
      	<xxxxxxxxxxxx>01</xxxxxxxxxxxx>
      	<xxxxxxxxxxx>2021</xxxxxxxxxxx>
      	<xxxxxxxxxxxxxxxx>xxxx</xxxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxxxx>x</xxxxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxx>xxx</xxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxx1>1600 xxxxxxxxxxxx xxxx.</xxxxxxxxxxxxxx1>
      	<xxxxxxxxxxxxxx2/>
      	<xxxxxxxxxxxx>555-8675-309</xxxxxxxxxxxx>
      	<xxxxxxxxxxx>xxxxxxxxxx</xxxxxxxxxxx>
      	<xxxxxxxxxxxx>xx</xxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxxxx>10123</xxxxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxxxxx>xx</xxxxxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxxxx>xxxxxxx</xxxxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxxx/>
      	<xxxxxxxxxxxxxxx1>1600 xxxxxxxxxxxx xxxx.</xxxxxxxxxxxxxxx1>
      	<xxxxxxxxxxxxxxx2/>
      	<xxxxxxxxxxxxx>555-123-4568</xxxxxxxxxxxxx>
      	<xxxxxxxxxxxx>xxxxxxxxxx</xxxxxxxxxxxx>
      	<xxxxxxxxxxxxx>xx</xxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxxxxx>10123</xxxxxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxxxxxx>xx</xxxxxxxxxxxxxxxxxxx>
      	<xxxx_xxxx_1>xxxx</xxxx_xxxx_1>
      	<xxxx_xxxx_1>xxxxx xxxx</xxxx_xxxx_1>
      	<xxxx_xxxxx_1>10000</xxxx_xxxxx_1>
      	<xxxx_xxxxxxxx_1>1</xxxx_xxxxxxxx_1>
      	<xxxx_xxx_1>8675309</xxxx_xxx_1>
      	<xxxxxxxxxxxx>1234</xxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxx>01</xxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxx>xxxxxxx</xxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxxxx>500</xxxxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxxxxxx>980</xxxxxxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxxxxx>1080</xxxxxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxx>-1:00</xxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxxxxx>xxxx</xxxxxxxxxxxxxxxxxx>
      	<xxxxxxxxx>127.0.0.1</xxxxxxxxx>
      	<xxxxxxxxx>xxxxxxx xxxxxxx-xxxxxxxxxx/3.1</xxxxxxxxx>
      	<xxxxxxxxxxxxx>xxxx/xxxx,xxxxxxxxxxx/xxxxx+xxx,xxxxxxxxxxx/xxx;x=0.9</xxxxxxxxxxxxx>
      	<xxxxxxxxxxxxx>xxx</xxxxxxxxxxxxx>
      	//<xxxxxxxxxx>01</xxxxxxxxxx>
      	<xxxxxxxxxxxxxxxxxxxxxxxx>03</xxxxxxxxxxxxxxxxxxxxxxxx>
      	<xxxxxxxxxxxxxxxxxxx>01,02</xxxxxxxxxxxxxxxxxxx>
      	<xxxxxxxx>xxx64xxx-x19x-4728-8849-x3x50xxxxx39</xxxxxxxx>
      	<xxxxxxxxxxxxx>${xxxxxxxxxxx}</xxxxxxxxxxxxx>
      	<xxxxxxxxxxx>12341234</xxxxxxxxxxx>
      	<xxxxxxxxxxxxx>xxxxxxxx</xxxxxxxxxxxxx>
      </xxxxxxxxxxx>

      So based on the # of characters I'm passing in vs what I'm getting logged doesn't add up - I have data that should be in "chunk 2" that is missing and that last bit should be "chunk 3"

       

    • Log4j2's avatar
      Log4j2
      Icon for Altocumulus rankAltocumulus

      Unfortunately logging to an HSL pool is not an option for me - that's more configuration and setup time than I've alloted for the details this irule should provide that I need for about a 24hr period.

      I just can't figure out why it's omitting a chunk of data, otherwise it works perfectly

      Looks like the post you linked is almost identifical to what I have except his loop isn't nested under an 'if' statement.  I could give that a try

  • How about somehting like this:

    for { set start 0; set end $static::max_chars} { $start < [HTTP::payload length] } { incr start $static::max_chars; incr end $static::max_chars } {
    	log local0.debug "$start:$end [string range [HTTP::payload] $start $end]"
    }
    • PeteWhite's avatar
      PeteWhite
      Icon for Employee rankEmployee

      In fact I have just grabbed this from an iRule i recently wrote. Almost the same, with fixed values. Note the end is 99 but the increment is 100. As you say, string range is zero-indexed

      for {set start 0; set end 99} {$start < [HTTP::payload length]} {incr start 100;incr end 100} {
                  log local0.debug "[string range [HTTP::payload] $start $end ]"
              }