# Connection/flow not detected in new\_connection but in connection\_state\_remove **URL:** \ **Category:** Zeek\ **Tags:** scripting, dnp3, events\ **Created:** [March 18, 2023, 5:58am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938 "2023-03-18T05:58:59Z")\ **Posts on this page:** 20\ **Page:** 1
**Author:** ![biswa](https://avatars.discourse-cdn.com/v4/letter/b/58956e/32.png) [@biswa](https://community.zeek.org/u/biswa)\ **Post date:** [March 18, 2023, 5:58am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/1 "2023-03-18T05:58:59Z")
I was trying to print new connection detected from the below pcap file [https://github.com/cisagov/icsnpp-dnp3/blob/main/tests/traces/dnp3\_example.pcap](https://github.com/cisagov/icsnpp-dnp3/blob/main/tests/traces/dnp3_example.pcap) The connection/flow from src port 20000 to dst port 20000 is not detected in new\_connection (total 10 connections detected) but connection\_state\_remove showing that connection/flow (total 11 connections). Why so? Regards, Subhajit ---
**Author:** ![Vern](https://yyz1.discourse-cdn.com/flex011/user_avatar/community.zeek.org/vern/32/630_2.png) [@Vern](https://community.zeek.org/u/Vern)\ **Post date:** [March 19, 2023, 12:55am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/2 "2023-03-19T00:55:13Z")
Hmmm when I use the following script it prints `11, 11`. This is with Zeek 5.0.5. ```auto global new_c = 0; global remove_c = 0; event new_connection(c: connection) { ++new_c; } event connection_state_remove(c: connection) { ++remove_c; } event zeek_done() { print new_c, remove_c; } ``` ---
**Author:** ![biswa](https://avatars.discourse-cdn.com/v4/letter/b/58956e/32.png) [@biswa](https://community.zeek.org/u/biswa)\ **Post date:** [March 19, 2023, 1:28am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/3 "2023-03-19T01:28:58Z")
Yes, sorry the question is incomplete . The issue is coming when I published the new\_connection data to a python module using broker framework. Locally inside zeek it is printing 11 new conn and 11 in remove conn, but when in the same script I connect to a peer and sending the new\_connection data, the first connection information is somehow lost and not received in the python script. I have started the python listener first then starting zeek with the pcap and zeek scripts . I am suspecting that first event is getting fired before peer is connected (peer connect code inside zeek\_init()) and event new connection func is also in the same script from where I am publishing that event. Thanks ---
**Author:** ![awelzel](https://yyz1.discourse-cdn.com/flex011/user_avatar/community.zeek.org/awelzel/32/609_2.png) [@awelzel](https://community.zeek.org/u/awelzel)\ **Post date:** [March 20, 2023, 11:12am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/4 "2023-03-20T11:12:46Z")
Hello @biswa , > I am suspecting that first event is getting fired before peer is connected (peer connect code inside zeek\_init()) and event new connection func is also in the same script from where I am publishing that event. You’re most likely on the right track here. What you can do is to [suspend\_processing()](https://docs.zeek.org/en/master/scripts/base/bif/zeek.bif.zeek.html#id-suspend_processing) within `zeek_init()` and then call [continue\_processing()](https://docs.zeek.org/en/master/scripts/base/bif/zeek.bif.zeek.html#id-continue_processing) within `Broker::peer_added` when the process reading the pcap observes the Python side showing up as peer. There’s a glitch with this approach: If you call `suspend_processing()`, the `network_time()` will end-up being the current time instead of pcap time. I’ve very recently [proposed to change this](https://github.com/zeek/zeek/pull/2872). If you are confused/surprised by the observed timestamps, this might be why. Feel free to provide details of your use-case or chime in on the PR. This is fairly advanced Zeek/Python/broker integration use-case, nice! 🙂 ---
**Author:** ![Jan](https://avatars.discourse-cdn.com/v4/letter/j/ce7236/32.png) [@Jan](https://community.zeek.org/u/Jan)\ **Post date:** [March 20, 2023, 11:43am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/5 "2023-03-20T11:43:01Z")
Another peculiarity that might be relevant here is the fact that Zeek will always process the first packet to initialize network time. Events generated by this packet might be handled before broker is peered. ---
**Author:** ![awelzel](https://yyz1.discourse-cdn.com/flex011/user_avatar/community.zeek.org/awelzel/32/609_2.png) [@awelzel](https://community.zeek.org/u/awelzel)\ **Post date:** [March 20, 2023, 2:41pm UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/6 "2023-03-20T14:41:24Z")
> [@Jan](#): > > Another peculiarity that might be relevant here is the fact that Zeek will always process the first packet to initialize network time. Oh! Thanks for that! This seems a bit random and “peculiarity” seems closer to “issue”. The mentioned PR actually changes this and at least Zeek’s test suite appears unaffected while it makes @biswa’s use-cases rather difficult. Maybe we get let go of that with 6.0. ---
**Author:** ![biswa](https://avatars.discourse-cdn.com/v4/letter/b/58956e/32.png) [@biswa](https://community.zeek.org/u/biswa)\ **Post date:** [March 21, 2023, 3:07am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/7 "2023-03-21T03:07:34Z")
Hi, I have tried with suspend\_processing() inside zeek\_init() and continue\_processing() inside peer\_added(), but it seems the first new\_connection() event is getting fired before that and because it is not yet established, peer is not receiving that message. ```auto **NEW** , [orig_h=10.10.20.5, orig_p=20000/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] **PEER ADDED** , [id=212f24f5-6aa3-567b-aa22-23d19479859e, network=[address=127.0.0.1, bound_port=60000/tcp]] NEW, [orig_h=10.10.20.5, orig_p=55355/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] NEW, [orig_h=10.10.20.5, orig_p=55356/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] NEW, [orig_h=10.10.20.5, orig_p=55357/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] NEW, [orig_h=10.10.20.5, orig_p=55358/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] NEW, [orig_h=10.10.20.5, orig_p=55359/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] NEW, [orig_h=10.10.20.5, orig_p=55361/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] NEW, [orig_h=10.10.20.5, orig_p=55362/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] NEW, [orig_h=10.10.20.5, orig_p=55363/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] NEW, [orig_h=10.10.20.5, orig_p=55366/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] NEW, [orig_h=10.10.20.5, orig_p=55370/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] REMOVE, [orig_h=10.10.20.5, orig_p=20000/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] REMOVE, [orig_h=10.10.20.5, orig_p=55355/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] REMOVE, [orig_h=10.10.20.5, orig_p=55356/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] REMOVE, [orig_h=10.10.20.5, orig_p=55357/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] REMOVE, [orig_h=10.10.20.5, orig_p=55358/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] REMOVE, [orig_h=10.10.20.5, orig_p=55359/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] REMOVE, [orig_h=10.10.20.5, orig_p=55361/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] REMOVE, [orig_h=10.10.20.5, orig_p=55362/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] REMOVE, [orig_h=10.10.20.5, orig_p=55363/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] REMOVE, [orig_h=10.10.20.5, orig_p=55366/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] REMOVE, [orig_h=10.10.20.5, orig_p=55370/tcp, resp_h=10.10.20.8, resp_p=20000/tcp] ``` ```auto event zeek_init() { suspend_processing(); Broker::peer(addr_to_uri(127.0.0.1), 60000/tcp); } event Broker::peer_added(ep: Broker::EndpointInfo, msg: string) { print "PEER ADDED", ep; continue_processing(); } event new_connection(c: connection) { print "NEW", c$id; Broker::publish(my_topic, new_conn_added, c); } event connection_state_remove(c: connection) { print "REMOVE", c$id; Broker::publish(my_topic, conn_removed, c); } ``` Please check if I am doing any mistake. Thanks ---
**Author:** ![awelzel](https://yyz1.discourse-cdn.com/flex011/user_avatar/community.zeek.org/awelzel/32/609_2.png) [@awelzel](https://community.zeek.org/u/awelzel)\ **Post date:** [March 21, 2023, 9:20am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/8 "2023-03-21T09:20:38Z")
> [@biswa](#): > > Please check if I am doing any mistake. Conceptually you’re not doing anything wrong. This is the unfortunate behavior of Zeek 5.2.0 in `zeek -r` mode. If it’s possible for you to build Zeek from `master` (or use the `docker pull zeek/zeek-dev`), the most recent version does not exhibit this behavior anymore. The previously mentioned `network_time()` issue still persists, so you might run into that next. ---
**Author:** ![biswa](https://avatars.discourse-cdn.com/v4/letter/b/58956e/32.png) [@biswa](https://community.zeek.org/u/biswa)\ **Post date:** [March 21, 2023, 10:15am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/9 "2023-03-21T10:15:53Z")
Hi, I have built zeek from source , branch taken master only. Version showing 6.0.0-dev.64 Thanks ---
**Author:** ![biswa](https://avatars.discourse-cdn.com/v4/letter/b/58956e/32.png) [@biswa](https://community.zeek.org/u/biswa)\ **Post date:** [March 22, 2023, 2:31pm UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/10 "2023-03-22T14:31:45Z")
Hi, I have compiled latest zeek and installed. I am getting two issues … 1. Although the first packet handling is fixed (coming new\_connection after peer\_added) but the code is going into an infinite loop. PEER ADDED, [id=3c0a8567-cbd5-5f26-b7b8-972ce4c0cde1, network=[address=127.0.0.1, bound\_port=60000/tcp]] NEW, [orig\_h=10.10.20.5, orig\_p=20000/tcp, resp\_h=10.10.20.8, resp\_p=20000/tcp] REMOVE, [orig\_h=10.10.20.5, orig\_p=20000/tcp, resp\_h=10.10.20.8, resp\_p=20000/tcp] NEW, [orig\_h=10.10.20.8, orig\_p=20000/tcp, resp\_h=10.10.20.5, resp\_p=20000/tcp] REMOVE, [orig\_h=10.10.20.8, orig\_p=20000/tcp, resp\_h=10.10.20.5, resp\_p=20000/tcp] NEW, [orig\_h=10.10.20.8, orig\_p=20000/tcp, resp\_h=10.10.20.5, resp\_p=20000/tcp] REMOVE, [orig\_h=10.10.20.8, orig\_p=20000/tcp, resp\_h=10.10.20.5, resp\_p=20000/tcp] NEW, [orig\_h=10.10.20.5, orig\_p=20000/tcp, resp\_h=10.10.20.8, resp\_p=20000/tcp] REMOVE, [orig\_h=10.10.20.5, orig\_p=20000/tcp, resp\_h=10.10.20.8, resp\_p=20000/tcp] NEW, [orig\_h=10.10.20.8, orig\_p=20000/tcp, resp\_h=10.10.20.5, resp\_p=20000/tcp] REMOVE, [orig\_h=10.10.20.8, orig\_p=20000/tcp, resp\_h=10.10.20.5, resp\_p=20000/tcp] NEW, [orig\_h=10.10.20.8, orig\_p=20000/tcp, resp\_h=10.10.20.5, resp\_p=20000/tcp] REMOVE, [orig\_h=10.10.20.8, orig\_p=20000/tcp, resp\_h=10.10.20.5, resp\_p=20000/tcp] NEW, [orig\_h=10.10.20.5, orig\_p=20000/tcp, resp\_h=10.10.20.8, resp\_p=20000/tcp] REMOVE, [orig\_h=10.10.20.5, orig\_p=20000/tcp, resp\_h=10.10.20.8, resp\_p=20000/tcp] NEW, [orig\_h=10.10.20.8, orig\_p=20000/tcp, resp\_h=10.10.20.5, resp\_p=20000/tcp] REMOVE, [orig\_h=10.10.20.8, orig\_p=20000/tcp, resp\_h=10.10.20.5, resp\_p=20000/tcp] NEW, [orig\_h=10.10.20.8, orig\_p=20000/tcp, resp\_h=10.10.20.5, resp\_p=20000/tcp] REMOVE, [orig\_h=10.10.20.8, orig\_p=20000/tcp, resp\_h=10.10.20.5, resp\_p=20000/tcp] NEW, [orig\_h=10.10.20.5, orig\_p=20000/tcp, resp\_h=10.10.20.8, resp\_p=20000/tcp] REMOVE, [orig\_h=10.10.20.5, orig\_p=20000/tcp, resp\_h=10.10.20.8, resp\_p=20000/tcp] 1. Version : /usr/local/zeek/bin/zeek --v /usr/local/zeek/bin/zeek version 6.0.0-dev.250 2. Using same zeek scripts, pcap etc. Running using /usr/local/zeek/bin/zeek -Cr scripts command 1. Another issue : if running python broker script before zeek, then peer is not getting connected. It is only working if python broker script is running beforehand. Thanks ---
**Author:** ![awelzel](https://yyz1.discourse-cdn.com/flex011/user_avatar/community.zeek.org/awelzel/32/609_2.png) [@awelzel](https://community.zeek.org/u/awelzel)\ **Post date:** [March 22, 2023, 3:49pm UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/11 "2023-03-22T15:49:27Z")
> Although the first packet handling is fixed (coming new\_connection after peer\_added) but the code is going into an infinite loop. I’m not able to reproduce this. I’m putting two scripts for testing at the end. If you post your full Zeek script / Python script for reproduction that could help, but maybe below gives enough to start with. Your output looks like maybe there’s another subscription or publish happening and you have a message loop. Any chance you’re using auto\_publish or re-publish messages back on the Python side? What topic name are you using? > Another issue : if running python broker script before zeek, then peer is not getting connected. It is only working if python broker script is running beforehand. I suspect that this is just the overly long default retry connect interval. Below script sets it to 1sec and either way around works. * * * These are the scripts for testing. Except for the `network_time()` being set to current time, things seem reasonable well with the version you’re using here. ```auto # biswa.py import sys import broker # Setup endpoint and connect to Zeek. with ( broker.Endpoint() as ep, ep.make_subscriber("/topic/connections") as sub, ep.make_status_subscriber(True) as ss): ep.listen("127.0.0.1", 60000) # Wait until connection is established. print("waiting for peer") st = ss.get() print(st, st.code()) print("waiting for messages") while True: (t, d) = sub.get() # Assume we only get events here that have a connection record # as their first parameter. We don't have field names... # https://github.com/zeek/zeek/discussions/2879 conn_id = d[2][1][0][0] print("received", t, conn_id) ``` ```auto # biswa.zeek # More timely reconnects (default: 30 seconds) redef Broker::default_connect_retry = 1sec; global my_topic = "/topic/connections"; global new_conn_added: event(c: connection); global conn_removed: event(c: connection); event zeek_init() { suspend_processing(); Broker::peer(addr_to_uri(127.0.0.1), 60000/tcp); } event Broker::peer_added(ep: Broker::EndpointInfo, msg: string) { print network_time(), "PEER ADDED", ep; continue_processing(); } event new_connection(c: connection) { print network_time(), "NEW", c$id, c$start_time; Broker::publish(my_topic, new_conn_added, c); } event connection_state_remove(c: connection) { print network_time(), "REMOVE", c$id, c$start_time; Broker::publish(my_topic, conn_removed, c); } event Pcap::file_done(path: string) { print network_time(), "DONE", path; terminate(); } ``` ---
**Author:** ![biswa](https://avatars.discourse-cdn.com/v4/letter/b/58956e/32.png) [@biswa](https://community.zeek.org/u/biswa)\ **Post date:** [March 22, 2023, 5:38pm UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/12 "2023-03-22T17:38:10Z")
Hi, Please check the scripts to generate the issue . **Zeek script** biswa@biswa:~/zeek$ cat /usr/local/zeek/share/zeek/site/my-test/main.zeek global my\_topic = “/topic/test”; global new\_conn\_added: event(c: connection); global conn\_removed: event(c: connection); global conn\_reused: event(c: connection); event zeek\_init() &priority=5 { ``` suspend_processing(); Broker::peer(addr_to_uri(127.0.0.1), 60000/tcp); Broker::subscribe(my_topic); ``` } event my\_attack\_events(c: connection) { print(cat("Got events from Py script: ", c)); } event Broker::peer\_added(ep: Broker::EndpointInfo, msg: string) { print “PEER ADDED”, ep; continue\_processing(); } event new\_connection(c: connection) { print “NEW”, c$id; Broker::publish(my\_topic, new\_conn\_added, c); } event connection\_state\_remove(c: connection) { print “REMOVE”, c$id; Broker::publish(my\_topic, conn\_removed, c); } event connection\_reused(c: connection) { Broker::publish(my\_topic, conn\_reused, c); } •••••••••••••••••••••••••••••••••••••••••••••••••••••••••• **Python script:-** (broker) biswa@biswa:~/broker\_demo$ cat broker\_test.py import sys import broker with broker.Endpoint() as ep, ep.make\_subscriber(“/topic/test”) as sub: ``` ep.listen("127.0.0.1", 60000) while True: (t, d) = sub.get() my_event = broker.zeek.Event(d) print("received {} -- {}".format(my_event.name(), my_event.args())) my_new_events = broker.zeek.Event("my_attack_events", my_event.args()[0]); ep.publish("/topic/test", my_new_events); ``` ---
**Author:** ![awelzel](https://yyz1.discourse-cdn.com/flex011/user_avatar/community.zeek.org/awelzel/32/609_2.png) [@awelzel](https://community.zeek.org/u/awelzel)\ **Post date:** [March 22, 2023, 6:06pm UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/13 "2023-03-22T18:06:07Z")
> Please check the scripts to generate the issue . Hmm… It’s working here without triggering an endless loop. Could you provide the full command you’re running? Please also ensure that the Python program is using the broker bindings from your most recent Zeek version (I’m setting PYTHONPATH explicitly). I doubt it’s caused by your pcap, but if you can, sharing it won’t hurt. ---
**Author:** ![biswa](https://avatars.discourse-cdn.com/v4/letter/b/58956e/32.png) [@biswa](https://community.zeek.org/u/biswa)\ **Post date:** [March 23, 2023, 2:37am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/14 "2023-03-23T02:37:21Z")
Hi, 1. Regarding python binding : if you check from the last dump shared that I am running the python script from my zeek/auxil/broker path itself. I have created virtual environment inside the auxil directory of zeek master branch. I have pulled all submodules (broker) as well so that both zeek and broker become latest. Broker compiled successfully and python binding also. The script is connecting fine with the zeek (no incompatibility issue, also if version mismatch python binding also fails generally). Only issue beside the infinite loop, I am getting is if I run python script after zeek, that is not connected anyway. 2. Pcap : [icsnpp-dnp3/dnp3\_example.pcap at main · cisagov/icsnpp-dnp3 · GitHub](https://github.com/cisagov/icsnpp-dnp3/blob/main/tests/traces/dnp3_example.pcap) Thanks ---
**Author:** ![biswa](https://avatars.discourse-cdn.com/v4/letter/b/58956e/32.png) [@biswa](https://community.zeek.org/u/biswa)\ **Post date:** [March 24, 2023, 10:44am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/15 "2023-03-24T10:44:26Z")
**Zeek commands** /usr/local/zeek/bin/zeek -Cr \ **Running Python script inside the venv of broker-python binding** python3 broker\_test.py What do you mean by explicitly setting PYTHONPATH? ---
**Author:** ![awelzel](https://yyz1.discourse-cdn.com/flex011/user_avatar/community.zeek.org/awelzel/32/609_2.png) [@awelzel](https://community.zeek.org/u/awelzel)\ **Post date:** [March 24, 2023, 11:51am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/16 "2023-03-24T11:51:32Z")
@biswa - sorry for the delay. I think I’m now understanding what you’re seeing. I’ve used your pcap and observe a lot of new\_connection / connection\_state\_remove events (This is not an endless loop, but it’s many more events than expected). This is Zeek still (grrr) forwarding network time to realtime in `zeek -r` mode when Broker and/or suspend\_processing() is involved. With the latest Zeek master version since yesterday (zeek version 6.0.0-dev.271), you can put the following into your zeek\_init() as a workaround: ```auto event zeek_init() &priority=5 { # Workaround for Broker setting network time to realtime # alternatively, put a "redef allow_network_time_forward=F" # at the beginning of the file. set_network_time(double_to_time(0.001)); suspend_processing(); ... } ``` I’ll propose a fix for this soon so that should not be needed anymore 🤞 Now, when you do `zeek -r` _and_ use broker, Zeek doesn’t terminate at the end of the pcap by default and network time stops moving forward. This means connection related timers don’t expire. Usually that happens during shutdown. So you likely need to force timer expiry by moving network time forward by a few hours once the pcap has been fully read. ```auto event Pcap::file_done(p: string) { # Done reading pcap, forward network_time() by # 2 hours to expire connection related timers now. # Alternative would be to call terminate() # here as that would trigger the timer draining, but # then we would likely miss some broker messages as we # exited. set_network_time(network_time() + double_to_interval(2 * 3600)); } ``` I hope this works for you and reach out if you observe more things weird. We’ve been changing a few things in that are very recently. ---
**Author:** ![biswa](https://avatars.discourse-cdn.com/v4/letter/b/58956e/32.png) [@biswa](https://community.zeek.org/u/biswa)\ **Post date:** [March 25, 2023, 5:06am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/17 "2023-03-25T05:06:44Z")
Hi @awelzel , Can you please elaborate the issue ? I am not able to understand why there are lots of new or remove conn coming for the same connection ! Can you please post the commit or PR id where you made the fixes for this. Thanks ---
**Author:** ![awelzel](https://yyz1.discourse-cdn.com/flex011/user_avatar/community.zeek.org/awelzel/32/609_2.png) [@awelzel](https://community.zeek.org/u/awelzel)\ **Post date:** [March 25, 2023, 4:35pm UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/18 "2023-03-25T16:35:14Z")
> Can you please elaborate the issue ? I am not able to understand why there are lots of new or remove conn coming for the same connection ! Currently, when Zeek processes the first Broker messages/commands, there’s a condition that checks whether network time is initialized already. If it is not, broker manager decides to set network time to the current time (wallclock). Even if reading traces via `zeek -r` and `suspend_processing()` where this isn’t really applicable. What then happens is that each individual packet from the pcap (which might be weeks, months or even years old) creates a new connection. The first packet creates a connection which is immediately considered timed-out because of the packet timestamp vs current network time discrepancy. So, `connection_state_remove` is invoked. The next packet then creates the connection again, triggering `new_connection`, but it’s immediately timed-out again, and so on. The `set_network_time(double_to_time(0.001));` essentially prevents that broker manager behavior. Alternatively setting `redef allow_network_time_forward=F` with current master will prevent it too and may look less like a workaround. I hope that all makes sense. > Can you please post the commit or PR id where you made the fixes for this. It’s not yet in master, but this is the PR: [Broker: Remove network time initialization by awelzel · Pull Request #2893 · zeek/zeek · GitHub](https://github.com/zeek/zeek/pull/2893) There’s also some information in the following issue, detailing some of these observations: > > > It has been reported that NICs with large packet buffers cause timing artifacts …when queued packets are too far in the past, exceeding syn timeouts, session timeouts or other inacitivity timeouts. > > A reproducer is below script. It busy-spins in script land to delay following packets by a configurable amount. When setting a delay of 7.0 seconds and monitoring curl requests to localhost, the conn.log ends-up as follows: A single connection is split into two: S and ^haD... > > \`\`\` > 1678370118.531234 CQn4ev3z8XHcCy2YSl ::1 44060 ::1 80 tcp - - - - S0 - - 0 S 1 80 0 0 - > 1678370118.531246 CFGEQm169HXtB8Yml7 ::1 44060 ::1 80 tcp http 0.000296 73 853 SF - - 0 ^hADadFf 5 433 5 1221- > 1678370119.538894 CJOlLt2M5Ay3NKYuWa ::1 44062 ::1 80 tcp - - - - S0 - - 0 S 1 80 0 0 - > 1678370119.538907 C7JLrC3fG5xULiKXfc ::1 44062 ::1 80 tcp http 0.000320 73 853 SF - - 0 ^hADadFf 5 433 5 1221- > \`\`\` > > Lowering the udp\_inacitivity\_timeout to 5secs using the same script, artifacts with UDP/DNS "connections" can be provoked (could also delay packets by 1min+). > > \`\`\` > 1678371136.705769 ChnpGk303HpQduR34c 172.17.0.2 51362 1.1.1.1 53 udp dns - - - S0 - - 0 D 1 77 0 0 - > 1678371136.726418 CPcZfF3pveTn9bNPOc 172.17.0.2 51362 1.1.1.1 53 udp dns - - - SHR - - 0 ^d 0 0 1 97 - > 1678371136.744709 CGamXJTIaAVSkIG3h 172.17.0.2 32817 1.1.1.1 53 udp dns - - - S0 - - 0 D 1 77 0 0 - > 1678371136.764838 CxNmCj2hOX7fk4zj06 172.17.0.2 32817 1.1.1.1 53 udp dns - - - SHR - - 0 ^d 0 0 1 97 - > \`\`\` > > Current understanding is that there are various places within Zeek where network time is forwarded to wallclock time fairly unconditionally (when in live mode at least) whether or not the packet source is dry or empty: > > \* In the Timer manager: https://github.com/zeek/zeek/blob/master/src/Timer.cc#L96-L102 > \* In the Event manager: https://github.com/zeek/zeek/blob/master/src/Event.cc#L192-L197 > \* In the main run loop: https://github.com/zeek/zeek/blob/master/src/RunState.cc#L326-L336 > \* In the Broker manager: https://github.com/zeek/zeek/blob/master/src/broker/Manager.cc#L1145-L1146 > > There is likely historic background to all these places: E.g. NICs with immense buffers and large or no block/segment timeouts delay timer expiration. Further, Zeek workers not receiving monitoring traffic at all would be stalling timer expiration altogether. > > A middle-ground would be to sticking to network\_time whenever possible (and packets are available), but not getting stuck when there's zero traffic. > > Some thoughts: > > \* Consolidate the network\_time to current\_time update into a single place rather than in the individual managers. > \* Only do the update if a live packet source as been idle for a configurable amount of time (100msec or 1second as default). > \* If a packet source batches up packets for longer than that, can reconfigure, but likely may want to fix the source, too. > \* Not exactly sure about the implementation. For polling packet sources we could track state/wallclock timestamps of \`ExtractNextPacket()\` results and have a \`IsIdle()\` method on PktSrc with a generic implementation that can be replaced if needed. > \* Not sure about the suspend\_processing interaction: Currently, one indicates to stop processing packets and at the same time this allows to change network time based on wallclock. A bit of looking at the history: Maybe that should only have been allowed in combination with pseudo\_realtime. > > @J-Gras is/was looking to suppress any kind of network\_time update from the wallclock which may fit here as well (either as a separate option or some sort of infinite idle time). IIRC he also ran into the suspend\_processing behavior and found it surprising. > > > \--- > > \`\`\` > \# delay.zeek > > \# E.g. use as follows > \# $ docker run -d --name nginx --network=host nginx > \# $ while true ; do curl localhost ; sleep 1 ; done > \# $ zeek -B tm,main-loop -f 'port 80 or port 53 or port 5353' -C -i lo delay.zeek Delay::delay\_by=7sec > > \## Busy-spin delay packets such that any pending packets in the NIC after > \## the current one are consumed \`\`delay\_by\`\` seconds delayed. > module Delay; > > export { > option delay\_by: interval = 0.0sec; > } > > event scheduled\_raw\_packet() > { > local cur\_pkt = get\_current\_packet(); > local pkt\_ts = cur\_pkt$ts\_sec + cur\_pkt$ts\_usec / 1000000.0; > local cur\_delay = time\_to\_double(current\_time()) - pkt\_ts; > print "stat", pkt\_ts, pkt\_ts + interval\_to\_double(delay\_by), "nt", network\_time(), "ct", current\_time(), cur\_delay; > } > > event raw\_packet(p: raw\_pkt\_hdr) &priority=100 > { > local cur\_pkt = get\_current\_packet(); > local pkt\_ts = cur\_pkt$ts\_sec + cur\_pkt$ts\_usec / 1000000.0; > > local cur\_delay = time\_to\_double(current\_time()) - pkt\_ts; > > # Busy spinning until we've delayed enough. > while ( pkt\_ts + interval\_to\_double(delay\_by) \> time\_to\_double(current\_time()) ) { } > > schedule 0.1sec { scheduled\_raw\_packet() }; > } > \`\`\` ---
**Author:** ![biswa](https://avatars.discourse-cdn.com/v4/letter/b/58956e/32.png) [@biswa](https://community.zeek.org/u/biswa)\ **Post date:** [March 26, 2023, 5:56pm UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/19 "2023-03-26T17:56:02Z")
Thanks for the reply! So, you are saying pcap’s total 834 packets will generate 834 new and 834 remove events each. I think it’s generating more than 834 connection, I will check once and confirm. Apart from this , the fix you suggested, disabling the network time forward, will it lead to take only current time ? Is this PR giving permanent or temporary fix to this problem? ---
**Author:** ![awelzel](https://yyz1.discourse-cdn.com/flex011/user_avatar/community.zeek.org/awelzel/32/609_2.png) [@awelzel](https://community.zeek.org/u/awelzel)\ **Post date:** [March 27, 2023, 9:03am UTC](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938/20 "2023-03-27T09:03:15Z")
> [@biswa](#): > > I think it’s generating more than 834 connection, I will check once and confirm. Yes, I’m seeing 834 conn.log entries and also 834 NEW (and REMOVED) messages for the dnp3\_example.pcap. Again, this isn’t “wanted” behavior, but an artifact of network time being set to the current time by broker manager. > Apart from this , the fix you suggested, disabling the network time forward, will it lead to take only current time ? The opposite, it’ll make sure that only timestamps from the packets in the pcap are used for network time. > Is this PR giving permanent or temporary fix to this problem? For your use-case of `zeek -r` in combination with broker connectivity the PR (if accepted) provides a permanent fix. For now, using `redef allow_network_time_forward=F` will also work for you. [Next page](https://community.zeek.org/t/connection-flow-not-detected-in-new-connection-but-in-connection-state-remove/6938.md?page=2)