Delaying Log Writes function is not work properly

[scyllaever]

zeek/base/protocols/conn.zeek event zeek_init() &priority=5 { Log::set_max_delay_interval(Conn::LOG, 10sec); ## set the max delay interval to 10 sec Log::create_stream(Conn::LOG, [$columns=Info, $ev=log_conn, $path="conn", $policy=log_policy]); }

event connection_state_remove(c: connection) &priority=-5 { Log::write(Conn::LOG, c$conn); ##Immediately output the result without waiting for 10 seconds even if there is no data associated with VIPRelation::vip_relation }

hook Log::log_stream_policy(rec: Conn::Info, id: Log::ID) { if ( id != Conn::LOG ) return; local token = Log::delay(id, rec);

VIPRelation::vip_relation is a table that dynamically adds data, and only writes associated data to rec when it contains rec$id$orig_h

when [id, rec, token] ( rec$id$orig_h in VIPRelation::vip_relation ) 
   {
    local entry = VIPRelation::vip_relation[rec$id$orig_h];
rec$account = entry$account;
rec$tenantId = entry$tenantId;
rec$session = entry$session;
rec$sip = entry$sip;
    Log::delay_finish(id, rec, token);
   }
timeout 10sec
   {
   Reporter::warning(fmt("lookup_addr timeout for %s", rec$id$orig_h));  
   Log::delay_finish(id, rec, token);
   }
}

When the 10 second timeout occurs, a large number of error records are found in the reporter.log

1731554048.553891 Reporter::WARNING lookup_addr timeout for 192.168.112.135 /opt/zeek/share/zeek/base/protocols/conn/main.zeek, line 339 1731554048.553891 Reporter::ERROR non-existing log record for token=1 0x5952690 (empty) 1731554048.756815 Reporter::WARNING lookup_addr timeout for 192.168.112.135 /opt/zeek/share/zeek/base/protocols/conn/main.zeek, line 339 1731554048.756815 Reporter::ERROR non-existing log record for token=2 0x3473b40 (empty) 1731554049.734079 Reporter::WARNING lookup_addr timeout for 192.168.112.135 /opt/zeek/share/zeek/base/protocols/conn/main.zeek, line 339 1731554049.734079 Reporter::ERROR non-existing log record for token=3 0x33fb1c0 (empty) 1731554050.605074 Reporter::WARNING lookup_addr timeout for 192.168.112.135 /opt/zeek/share/zeek/base/protocols/conn/main.zeek, line 339 1731554050.605074 Reporter::ERROR non-existing log record for token=4 0x4e58ca0 (empty)

[awelzel]

Hello @scyllaever - thanks for the report and trying this feature. This might be easier in the forum or on Slack.

This looks okay, the only thing that makes me pause is that the configured max delay and the when timeout are both 10 seconds. This may result in the when timeout firing after the event was logged and isn't actively delayed anymore.

You can pass a post_delay_cb do Log::delay() to debug this.

        local token = Log::delay(id, rec, function(cb_rec: any, cb_id: Log::ID): bool {
                local crec = cb_rec as Conn::Info;
                Reporter::info(fmt("post delay callback for %s", crec$id$orig_h));
                return T;
        });

You'll likely see "post delay callback" messages before the warnings and errors.

The fix is to use a shorter when timeout to make sure the log record is still being delayed when Log::delay_finish() is called.

A 10 second delay is also pretty long. It's advisable to use a shorter default and instead re-delay a record within the post delay callback multiple times (this provides an opportunity to log or update metrics if certain records are delayed very long).

https://docs.zeek.org/en/lts/frameworks/logging.html#delaying-log-writes

Zeek delays a log record by a configurable interval defined for each log stream. It defaults to the global Log::default_max_delay_interval, and can be adapted by calling Log::set_max_delay_interval on the stream. It is possible to explicitly extend the delay duration by providing a post delay callback to Log::delay. Calling Log::delay from within such a post delay callback re-delays the record, essentially putting it at the end of the per-stream queue again.

Hope this helps - I'll close the ticket unless there's more questions.

[scyllaever]

Hello @scyllaever - thanks for the report and trying this feature. This might be easier in the forum or on Slack.

This looks okay, the only thing that makes me pause is that the configured max delay and the when timeout are both 10 seconds. This may result in the when timeout firing after the event was logged and isn't actively delayed anymore.

You can pass a post_delay_cb do Log::delay() to debug this.

        local token = Log::delay(id, rec, function(cb_rec: any, cb_id: Log::ID): bool {
                local crec = cb_rec as Conn::Info;
                Reporter::info(fmt("post delay callback for %s", crec$id$orig_h));
                return T;
        });

You'll likely see "post delay callback" messages before the warnings and errors.

The fix is to use a shorter when timeout to make sure the log record is still being delayed when Log::delay_finish() is called.

A 10 second delay is also pretty long. It's advisable to use a shorter default and instead re-delay a record within the post delay callback multiple times (this provides an opportunity to log or update metrics if certain records are delayed very long).

https://docs.zeek.org/en/lts/frameworks/logging.html#delaying-log-writes

Zeek delays a log record by a configurable interval defined for each log stream. It defaults to the global Log::default_max_delay_interval, and can be adapted by calling Log::set_max_delay_interval on the stream. It is possible to explicitly extend the delay duration by providing a post delay callback to Log::delay. Calling Log::delay from within such a post delay callback re-delays the record, essentially putting it at the end of the per-stream queue again.

Hope this helps - I'll close the ticket unless there's more questions.

event zeek_init() &priority=5 {

Log::set_max_delay_interval(Conn::LOG, 10sec); ## wrong

Log::create_stream(Conn::LOG, [$columns=Info, $ev=log_conn, $path="conn", $policy=log_policy]); Log::set_max_delay_interval(Conn::LOG, 10sec); ## correct }

Thanks for your response. It was my mistake, as Log::set_max_delay_interval was called in the wrong place (Must be called after Log::create_stream ), which caused the setting to not take effect (always 200msec). Therefore, when timeout 10sec is invalid regardless of how long it is set