Forum Discussion
Log4j2
Altocumulus
AltocumulusiRule [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 ]" }
- Nikoolayy1
MVP
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
Log4j2So 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>xxchunk2 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"
- Nikoolayy1
Hello, There are a lot of community articles about this for example https://community.f5.com/t5/crowdsrc/log-http-request-and-response-payload-via-hsl-and-locally/ta-p/284294 . My last idea is to send the logs as I mentioned to external log server as the limit is 1024 for an http request and the different chrunks seem to be considered a part of a single request as F5 needs to gather all the chrunks for inspection by for example the WAF policy etc.
- Log4j2
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
PeteWhiteEmployee
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
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 ]" }
