[Zeek] http body q.

[Dk Jack]

Hi Jon,
I've attached a minimal script that does what I am describing. However,
when I try this minimal script on try.bro.org it works correctly as I
expected. However, in my cluster setup, the end_entity event from response
body is coming first, then log-filter call, followed by end entity call for
request. Since I have other events I am processing for the request, not
sure if they are affecting the order. Giving a priority of 10 for the
end_entity event did not fix it either. Running the minimalist script I
gave here also causes the problem on my system but not try.bro.org website.
Really puzzling :(

fyi, I've included the logs I see in my reporter log which indicates the
order of the events at the end of this email

Dk.

PS: pcap link https://www.dropbox.com/s/epx2nz60d06uor9/long-user.pcap?dl=0

@load base/protocols/http/main

module HTTP;

export {
  redef record Info += {
    request_body: string &log &optional;
    request_body_complete: bool &log &default=F;

    response_body: string &log &optional;
    response_body_complete: bool &log &default=F;
    log_pred: bool &default=T;
  };
}

event bro_init()
{
  Log::remove_default_filter(HTTP::LOG);
  Log::add_filter(HTTP::LOG, [$name="new-default",
                              $pred(rec: HTTP::Info) = {
                                Reporter::info(fmt("request body complete:
%s, bsize=%d"
                                                   ,
rec$request_body_complete?"true":"false"
                                                   , |rec$request_body|));
                                return rec$log_pred;
                              }
                             ]);
}

event http_entity_data(c: connection, is_orig: bool, length: count, data:
string)
{
  if (is_orig) {
    # request body accumulation
    if (is_orig && !c$http?$request_body)
      c$http$request_body = "";

    c$http$request_body += data;
  } else {
    # response body accumulation.
    if (!is_orig && !c$http?$response_body)
      c$http$response_body = "";

    c$http$response_body += data;
  }
}

event http_end_entity(c: connection, is_orig: bool)
{
  Reporter::info(fmt("%s: end_entity called for %s, bsize=%d"
                     , c$uid, is_orig?"request":"response",
|c$http$request_body|));

  if (is_orig) {
    if (|c$http$request_body| > 0) {
      c$http$request_body = encode_base64(c$http$request_body);
      c$http$request_body_complete = T;
    }
  } else {
    if (|c$http$response_body| > 0) {
      c$http$response_body = encode_base64(c$http$response_body);
      c$http$response_body_complete = T;
    }
  }
}

Logs order on my setup:
--------------------------------
1564527256.318960 Reporter::INFO CHhIoL3bq5EEA89mE6: end_entity called for
response, resp_bsize=14182
/opt/bro/spool/installed-scripts-do-not-touch/site/large-body.bro,
lines 51-52
1564527256.318960 Reporter::INFO log-filter: body complete: false,
bsize=5494 /opt/bro/spool/installed-scripts-do-not-touch/site/large-body.bro,
lines 21-23
1564527256.318960 Reporter::INFO CX7yqa4u6bAe5Jiyx8: end_entity called for
request, req_bsize=5494
/opt/bro/spool/installed-scripts-do-not-touch/site/large-body.bro,
lines 51-52

Logs order on try.bro.org:
----------------------------------
1564517218.391577 ././trybro.bro, lines 51-52: CS3JwH1fT1mceM8uF5:
end_entity called for request, req_bsize=42179
1564517218.391807 ././trybro.bro, lines 51-52: CS3JwH1fT1mceM8uF5:
end_entity called for response, req_bsize=56240
1564517218.391807 ././trybro.bro, lines 21-23: log-filter body complete:
true, bsize=56240


On Tue, Jul 30, 2019 at 9:41 AM Jon Siwek <jsiwek at corelight.com> wrote:

> On Mon, Jul 29, 2019 at 6:59 PM Dk Jack <dnj0496 at gmail.com> wrote:
>
> >> This seems to work fine for small bodies. However, for large bodies, I
> noticed that the log gets written without the body getting encoded.
>
> For performance reasons, there's an option which throttles the maximum
> amount of data provided in entity_data events to 1500 bytes by
> default:
>
>
> https://docs.zeek.org/en/stable/scripts/base/init-bare.bro.html#id-http_entity_data_delivery_size
>
> So you can see if changing that `http_entity_data_delivery_size`
> option works for you.
>
> > Is there something I can do to ensure my end_entity event is invoked
> before http_log event is called? Any input is appreciated. Thanks.
>
> I think normally that should not be the order of things.  Might be
> easier to explain what's going on if you provide an example script and
> pcap that reproduces what you are seeing.
>
> - Jon
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mailman.ICSI.Berkeley.EDU/pipermail/zeek/attachments/20190730/8deb7142/attachment.html