Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Option change handler invoked after zeek_done() event #2010

Closed
awelzel opened this issue Mar 25, 2022 · 1 comment · Fixed by #2297
Closed

Option change handler invoked after zeek_done() event #2010

awelzel opened this issue Mar 25, 2022 · 1 comment · Fixed by #2297
Assignees
Labels
Area: Scripting good first issue A good place to get started working with Zeek. Type: Bug 🐛 Unexpected behavior or output.

Comments

@awelzel
Copy link
Contributor

awelzel commented Mar 25, 2022

In a package of ours we are accessing a Broker::Store handle in a change handler. We got bitten by "invalid Broker store handle" when the change handler is invoked during/after shutdown.

Chatting with @rsmmr / @ckreibich about change handlers and broker stores, there was slight surprise to hear that these are invoked after zeek_done() and it was suggested to open a ticket.

The following reduced script shows the issue we observe.

redef Config::config_files += { "./my_option.dat" };
module Test;

global store: opaque of Broker::Store;

export {
    option my_option = "test";
}

function change_handler(id: string, new_value: string): string {
  print(fmt("%s change_handler() zeek_is_terminating=%s store_is_closed=%s store=%s", current_time(), zeek_is_terminating(), Broker::is_closed(store), store));
  Broker::put(store, "my_option", new_value);
  return new_value;
}

event zeek_done() {
  print(fmt("%s zeek_done() zeek_is_terminating=%s store_is_closed=%s store=%s", current_time(), zeek_is_terminating(), Broker::is_closed(store), store));
}

event zeek_init() {
  Option::set_change_handler("Test::my_option", change_handler);
  store = Broker::create_master("my_store");
  print(fmt("%s zeek_init() store_is_closed=%s store=%s ", current_time(), Broker::is_closed(store), store));
}

my_option.dat

Test::my_option updated
$ zeek ./my_option_store.zeek 
1648205596.193555 zeek_init() store_is_closed=F store=broker::store::{my_store} 
1648205596.194328 zeek_done() zeek_is_terminating=T store_is_closed=F store=broker::store::{my_store}
1648205596.194757 change_handler() zeek_is_terminating=T store_is_closed=T store=broker::store::{}
error in ././my_option_store.zeek, line 13: invalid Broker store handle (Broker::put(Test::store, to_any_coercemy_option, to_any_coerceTest::new_value, 0 secs) and broker::store::{})

As an aside, it could be argued that the above script should just rely on option/configuration framework (agree, but it's also the reduced version). But change handlers being invoked after zeek_done() has happened still seems a vaild issue to discuss.

@0xxon
Copy link
Member

0xxon commented Mar 30, 2022

Yup, seems like a bug - change handlers probably should not be executing when zeek_is_terminating=T.

@0xxon 0xxon added good first issue A good place to get started working with Zeek. Type: Bug 🐛 Unexpected behavior or output. Area: Scripting labels Mar 30, 2022
@awelzel awelzel self-assigned this Jul 25, 2022
awelzel added a commit that referenced this issue Jul 25, 2022
Due to the asynchronous behavior of the input framework and broker
communication, change handlers were previously called even after
zeek_done() event processing completed and also broker shutdown.

Accessing broker store handles within change handlers this late
triggered invalid Broker store handle messages:

    error in ././my_option_store.zeek, line 13: invalid Broker store handle (Broker::put(Test::store, to_any_coercemy_option, to_any_coerceTest::new_value, 0 secs) and broker::store::{})

Fixes #2010
awelzel added a commit that referenced this issue Jul 25, 2022
Due to the asynchronous behavior of the input framework and broker
communication, change handlers were previously called even after
zeek_done() event processing completed and also broker shutdown.

Accessing broker store handles within change handlers this late
triggered invalid Broker store handle messages:

    error in ././my_option_store.zeek, line 13: invalid Broker store handle (Broker::put(Test::store, to_any_coercemy_option, to_any_coerceTest::new_value, 0 secs) and broker::store::{})

Fixes #2010
@timwoj timwoj closed this as completed in 11cde53 Aug 3, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Area: Scripting good first issue A good place to get started working with Zeek. Type: Bug 🐛 Unexpected behavior or output.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants