Bug #4200
openFlows not deleted in bpf ipv4_maps
Description
OS: CentOS 8
Suricata version: 6.0.0
It is observed that the ipv4_maps is growing until max limits, currently testing with map size of 627680, and the ipv4_fail counter is growing.
Observed that in line 429 in flow-manager.c (FlowManagerHashRowClearEvictedList), flows added to the evicted list does not run FlowBypassedTimeout, and these flows are not removed from the map. Changed this function to:
420 static void FlowManagerHashRowClearEvictedList(FlowManagerTimeoutThread *td,
421 Flow *f, struct timeval *ts, FlowTimeoutCounters *counters)
422 {
423 do {
424 FLOWLOCK_WRLOCK(f);
425 Flow *next_flow = f->next;
426 f->next = NULL;
427 f->fb = NULL;
428
429 //DEBUG_VALIDATE_BUG_ON(f->use_cnt > 0 || !FlowBypassedTimeout(f, ts, counters));
430 if (f->use_cnt > 0 || !FlowBypassedTimeout(f, ts, counters)) {
431 FLOWLOCK_UNLOCK(f);
432 f = f->next;
433 continue;
434 }
435
436 FlowQueuePrivateAppendFlow(&td->aside_queue, f);
437 /* flow is still locked in the queue */
438
439 f = next_flow;
440 } while (f != NULL);
441 }
and this seems to ensure that the map is not growing until the max. However, I am not that familiar with the code, so it might be reason not to it this way.
Another observation is that ipv4_maps_count does not reach zero when stopping the traffic towards Suricata, which I would expect and might in worst case bypass traffic that has never happened if it executed on the same IP/Ports.
Files
Updated by Victor Julien over 3 years ago
Do you have more insight into what the sequence of events leading up to this is? The check is there because it should not be possible to have a flow with these conditions in the evicted list. It should not have been evicted.
Updated by Odin Jenseg over 3 years ago
Not currently sure of what types of events that is leading up to this, but I try to do some research into this. What I can say at this stage, is that there is a huge differences in the amount a *flow_bypassed.closed comparing Suricata5 and Suricata6. It is great if you got any tips for debugging, or stats that I should share.
Updated by Odin Jenseg over 3 years ago
Did some testing today with Suricata 5.0.6, and observed similar issues that the ipv4_maps map did contain flows that was not accounted for.
How it was tested: Run Suricata for a while, then stop forwarding traffic to the listeninterface.
Results: 8 flows (16 keys in the map) that did not get deleted by Suricata.
Using the keys I could identify the flows in Suricata flow logging, these was marked as local bypassed. So most likely there has been happening a downgrade https://github.com/OISF/suricata/blob/master/src/flow.c#L408.
I dont see how it makes sense for this to be happening since the ts of the new packet should be larger than 50 seconds. The flow itself is larger than 50 seconds, but then it should be bypassed in the EBPF code.
We are using the default ebpf code located at git; bypass_filter.c.
Difficult to say if these are related to what we have observed during suricata6 testing.
If I am correct, local bypass in the stats log should only be incremented during a downgrade. A downgrade should be the only thing that can mark a flow as local bypass?
So if this is correct;
1. Flow is marked as FLOW_STATE_CAPTURE_BYPASSED.
2. Flow is downgraded to FLOW_STATE_LOCAL_BYPASSED
3. Since the flow is downgraded, entries in ipv4_maps is never accounted for.
Let me know if there are any other valuable information I can provide.
Updated by Odin Jenseg over 3 years ago
Did a quick test with GDB now, and it did not break on downgrade, but instead in the following line: https://github.com/OISF/suricata/blob/master/src/decode.c#L440
the p->BypassPacketsFlow is null, and is therefore failing the first if statement.
Updated by Odin Jenseg over 3 years ago
A bit to fast writing, but summarized.
Downgrade:
In GDB we did hit the local bypass downgrade https://github.com/OISF/suricata/blob/master/src/flow.c#L408, and it is correct based on the code, that the timestamp between packet and last TS i flow is larger then FLOW_BYPASSED_TIMEOUT / 2. How flows are passed Suricata when the flow state is FLOW_STATE_CAPTURE_BYPASSED is a not know yet, but I think that this leads to salutations where a flow is downgraded to local bypass and flows in the EBPF map is never accounted for sine they have the state FLOW_STATE_LOCAL_BYPASSED instead of FLOW_STATE_CAPTURE_BYPASSED.
https://github.com/OISF/suricata/blob/master/src/decode.c#L440:
In regards to the observation seen here, are those related to "fake" packets created in FlowFinish. As the packet source was PKT_SRC_FFR. Those packets does not have BypassPacketsFlow function set to AFPBypassCallback, and is therefore locally bypassed instead of capture bypass.
Updated by Odin Jenseg almost 2 years ago
I did some more deep dive into this for Suricata 7.
1. I did setup a breakpoint on https://github.com/OISF/suricata/blob/1fafb83fed2b03c9f8730f6cd191a6b4299ff489/src/flow-hash.c#L704 using GDB
2. When it hit, I could see that thread_id was not equal to tv.id.
3. I also checked the flow_state, which was equal towards 4. Which is FLOW_STATE_CAPTURE_BYPASSED (https://github.com/OISF/suricata/blob/e46a0bd46a590a2cfbd1b9ddad0d152b4274790b/src/flow.h#L517)
If I understand this correct then, it means that an CAPTURE_BYPASSED flow was marked as evicted, and ends up in the evicted list handled by the flow manager.
Also, one thing that I finds suspicious is that the amount of entries cleaned up in the eBPF map is not equal to the amount of timeout flows marked as capture_bypassed.
FR#01.flow.end.state.capture_bypassed vs FM#01.flow_bypassed.closed
