@memodi correct if I'm wrong, this was seen with IPFIX sampling = 1, so this is a situation where we know we're putting pressure on OVS.

yes, that(In reply to Joel Takvorian from comment #2)
> @memodi correct if I'm wrong, this was seen with IPFIX sampling =
> 1, so this is a situation where we know we're putting pressure on OVS.

yes, that's right. IPFIX sampling rate was 1:1. More info on the cluster nodes and resources:

Cloud provider: AWS
Number of masters: 3
Number of infra nodes: 3
Number of worker nodes: 9
Type of nodes: m5.2xlarge (8 vCPU and 32GB memory)

I have maybe the same issue when I use 1:1 ipfix sampling on OVS; I say "maybe" because my cluster becomes unaccessible very soon after I enable the exports, so I can't even check node logs & status. Note that my cluster setup is smaller than Mehul's one: just 3 compute nodes and 1 master.

It seems to be a regression since 4.10. In 4.10, with same user workloads, using ipfix export with 1:1 sampling generates some load but the cluster remains stable.
Let me know if I should open a different BZ
Thanks

Do you have the logs since boot time to find out the first error?
Because the log provided starts with:
-- Logs begin at Wed 2022-06-22 16:31:25 UTC, end at Thu 2022-06-30 21:13:06 UTC. --
Jun 30 14:57:38 ip-10-0-138-48 kernel: oauth-proxy: page allocation failure: order:2, mode:0x48c020(GFP_ATOMIC|__GFP_COMP|__GFP_ZERO), nodemask=(null),cpuset=crio-ad68d4d317837a768fb060e0fa1527316ce99dd1c20b72e58c88f221aeaf8241.scope,mems_allowed=0
Jun 30 14:57:38 ip-10-0-138-48 kernel: ena 0000:00:05.0 ens5: Failed to allocate strings_buf


which points to another failure before OVS or ena.

fbl

Logfile is actually reversed, but Flavio's point stands.

First memory exhaustion message is:

Jun 30 12:42:59 ip-10-0-138-48 kernel: swapper/6: page allocation failure: order:2, mode:0x48c020(GFP_ATOMIC|__GFP_COMP|__GFP_ZERO), nodemask=(null),cpuset=/,mems_allowed=0

But there's a lot going on much earlier than that. Some stuff can't talk to etcd around:

Jun 30 07:30:53 ip-10-0-138-48 hyperkube[2058]: I0630 07:30:53.230781    2058 status_manager.go:710] "Failed to delete status for pod" pod="testuser-1-1/django-psql-persistent-1-7jrbc" err="etcdserver: request t
imed out"
Jun 30 08:52:22 ip-10-0-138-48 hyperkube[2058]: E0630 08:52:22.720979    2058 controller.go:187] failed to update lease, error: Operation cannot be fulfilled on leases.coordination.k8s.io "ip-10-0-138-48.us-east
-2.compute.internal": the object has been modified; please apply your changes to the latest version and try again
Jun 30 08:52:22 ip-10-0-138-48 hyperkube[2058]: E0630 08:52:22.714067    2058 controller.go:187] failed to update lease, error: etcdserver: request timed out

and escalate to the point where:

Jun 30 10:07:30 ip-10-0-138-48 hyperkube[2058]: E0630 10:07:30.472633    2058 kubelet_node_status.go:487] "Error updating node status, will retry" err="failed to patch status \"{\\\"status\\\":{\\\"$setElementOr
der/conditions\\\":[{\\\"type\\\":\\\"MemoryPressure\\\"},{\\\"type\\\":\\\"DiskPressure\\\"},{\\\"type\\\":\\\"PIDPressure\\\"},{\\\"type\\\":\\\"Ready\\\"}],\\\"conditions\\\":[{\\\"lastHeartbeatTime\\\":\\\"2
022-06-30T10:07:23Z\\\",\\\"type\\\":\\\"MemoryPressure\\\"},{\\\"lastHeartbeatTime\\\":\\\"2022-06-30T10:07:23Z\\\",\\\"type\\\":\\\"DiskPressure\\\"},{\\\"lastHeartbeatTime\\\":\\\"2022-06-30T10:07:23Z\\\",\\\
"type\\\":\\\"PIDPressure\\\"},{\\\"lastHeartbeatTime\\\":\\\"2022-06-30T10:07:23Z\\\",\\\"type\\\":\\\"Ready\\\"}]}}\" for node \"ip-10-0-138-48.us-east-2.compute.internal\": etcdserver: request timed out"
Jun 30 10:07:26 ip-10-0-138-48 hyperkube[2058]: E0630 10:07:26.632962    2058 controller.go:187] failed to update lease, error: Put "https://api-int.memodi-preserve-ipfix-0622.qe-lrc.devcluster.openshift.com:644
3/apis/coordination.k8s.io/v1/namespaces/kube-node-lease/leases/ip-10-0-138-48.us-east-2.compute.internal?timeout=10s": net/http: request canceled (Client.Timeout exceeded while awaiting headers)

Jun 30 10:35:36 ip-10-0-138-48 hyperkube[2058]: E0630 10:35:36.423160    2058 reflector.go:138] object-"openshift-cluster-csi-drivers"/"openshift-service-ca.crt": Failed to watch *v1.ConfigMap: failed to list *v
1.ConfigMap: the server was unable to return a response in the time allotted, but may still be processing the request (get configmaps)

Basically, it looks like stuff can't talk to the apiservers.

Then even storage operations get slow:

Jun 30 11:14:36 ip-10-0-138-48 hyperkube[2058]: I0630 11:14:36.299093    2058 fsHandler.go:133] fs: disk usage and inodes count on following dirs took 4.441313822s: [/var/lib/containers/storage/overlay/64a171120
65acc91d7701b368fefcc7f5de4044b30dca1b905c9ef284b111d72/diff ]; will not log again for this container unless duration exceeds 3s

simple disk-based readiness probes fail:

Jun 30 11:20:29 ip-10-0-138-48 hyperkube[2058]: I0630 11:20:28.900279    2058 prober.go:121] "Probe failed" probeType="Readiness" pod="openshift-ovn-kubernetes/ovnkube-node-8hm8t" podUID=ac5361a7-8cda-43e3-b1d9-62f2a3494085 containerName="ovnkube-node" probeResult=failure output="command \"test -f /etc/cni/net.d/10-ovn-kubernetes.conf\" timed out"

And finally certificates time out because they couldn't be resigned (probably because of no access to apiserver):

Jun 30 11:21:18 ip-10-0-138-48 hyperkube[2058]: E0630 11:20:36.494068    2058 server.go:274] "Unable to authenticate the request due to an error" err="[verifying certificate SN=1540132601459492208525771308105021
92155, SKID=, AKID=B0:9E:63:08:5A:5E:B4:C0:59:29:24:DA:66:9E:4D:D9:3B:2E:40:E2 failed: x509: certificate signed by unknown authority, context canceled]"

and it's all downhill from there. The system is clearly under some kind of unexpected pressure much earlier than the kernel oops show; but those indicate eventually running out of kernel memory.

@fleitner - do you need the log files from the previous boot than the one I added  https://drive.google.com/file/d/13jbNJo3KzVRkZgtTbr1pHyNuuU3fEBns/view?usp=sharing ?  the log file is reversed.

No, the log is reversed as hinted already.

The only thing from OVS are the following messages that seem to be replies to OVN:
Jun 30 13:06:58 ip-10-0-138-48 ovs-vswitchd[1290]: ovs|106015|rconn|ERR|br-int<->unix#429461: no response to inactivity probe after 60 seconds, disconnecting
Jun 30 13:01:03 ip-10-0-138-48 ovs-vswitchd[1290]: ovs|106014|connmgr|INFO|br-int<->unix#429461: sending OFPBFC_MSG_FAILED error reply to OFPT_BUNDLE_CONTROL message
Jun 30 13:01:03 ip-10-0-138-48 ovs-vswitchd[1290]: ovs|106013|connmgr|INFO|br-int<->unix#429461: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_BUNDLE_ADD_MESSAGE message
Jun 30 13:00:14 ip-10-0-138-48 ovs-vswitchd[1290]: ovs|106012|connmgr|INFO|br-int<->unix#429461: sending OFPBFC_MSG_FAILED error reply to OFPT_BUNDLE_CONTROL message
Jun 30 13:00:14 ip-10-0-138-48 ovs-vswitchd[1290]: ovs|106011|connmgr|INFO|br-int<->unix#429461: sending OFPGMFC_GROUP_EXISTS error reply to OFPT_BUNDLE_ADD_MESSAGE message
Jun 30 13:00:14 ip-10-0-138-48 ovs-vswitchd[1290]: ovs|106010|connmgr|INFO|br-int<->unix#429461: sending OFPBFC_MSG_FAILED error reply to OFPT_BUNDLE_CONTROL message
Jun 30 13:00:14 ip-10-0-138-48 ovs-vswitchd[1290]: ovs|106009|connmgr|INFO|br-int<->unix#429461: sending OFPBAC_BAD_OUT_GROUP error reply to OFPT_BUNDLE_ADD_MESSAGE message
Jun 30 13:00:11 ip-10-0-138-48 ovs-vswitchd[1290]: ovs|106008|connmgr|INFO|br-int<->unix#429461: sending OFPBFC_TIMEOUT error reply to OFPT_BUNDLE_CONTROL message
Jun 30 12:56:30 ip-10-0-138-48 ovs-vswitchd[1290]: ovs|106007|rconn|ERR|br-int<->unix#3467: no response to inactivity probe after 60 seconds, disconnecting
Jun 30 11:14:23 ip-10-0-138-48 ovs-vswitchd[1290]: ovs|105916|bridge|INFO|bridge br-int: added interface d1e06976af94785 on port 2453

The first kernel error seems to be:
Jun 23 21:50:13 ip-10-0-138-48 kernel: Hardware name: Amazon EC2 m5.2xlarge/, BIOS 1.0 10/16/2017
Jun 23 21:50:13 ip-10-0-138-48 kernel: CPU: 0 PID: 2088349 Comm: httpd Not tainted 4.18.0-372.9.1.el8.x86_64 #1
Jun 23 21:50:13 ip-10-0-138-48 kernel: httpd invoked oom-killer: gfp_mask=0x6000c0(GFP_KERNEL), order=0, oom_score_adj=984


The task state list is below:
Jun 23 21:50:14 ip-10-0-138-48 kernel: [2091069] 1002930000 2091069    32169    11795   299008        0           984 perl-fcgi
Jun 23 21:50:14 ip-10-0-138-48 kernel: [2091068] 1002930000 2091068    33868    12994   311296        0           984 perl-fcgi
Jun 23 21:50:14 ip-10-0-138-48 kernel: [2091067] 1002930000 2091067    33879    13029   311296        0           984 perl-fcgi
Jun 23 21:50:14 ip-10-0-138-48 kernel: [2091066] 1002930000 2091066    32178    11796   294912        0           984 perl-fcgi
Jun 23 21:50:14 ip-10-0-138-48 kernel: [2091065] 1002930000 2091065    33879    12984   315392        0           984 perl-fcgi
Jun 23 21:50:14 ip-10-0-138-48 kernel: [2091064] 1002930000 2091064    33876    13011   303104        0           984 perl-fcgi
Jun 23 21:50:14 ip-10-0-138-48 kernel: [2091063] 1002930000 2091063    33868    13010   311296        0           984 perl-fcgi
Jun 23 21:50:14 ip-10-0-138-48 kernel: [2091062] 1002930000 2091062    33879    12990   315392        0           984 perl-fcgi
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2091054] 1002930000 2091054    30877    11629   278528        0           984 perl-fcgi-pm
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2091053] 1002930000 2091053    30852    11630   290816        0           984 perl-fcgi-pm
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2091052] 1002930000 2091052    30853    11673   286720        0           984 perl-fcgi-pm
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2091051] 1002930000 2091051    30854    11646   294912        0           984 perl-fcgi-pm
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2091050] 1002930000 2091050    30875    11646   290816        0           984 perl-fcgi-pm
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2091049] 1002930000 2091049    30868    11643   286720        0           984 perl-fcgi-pm
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2091048] 1002930000 2091048    30854    11636   286720        0           984 perl-fcgi-pm
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2091047] 1002930000 2091047    30870    11584   290816        0           984 perl-fcgi-pm
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2088507] 1002930000 2088507    33883    13018   307200        0           984 perl-fcgi
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2088460] 1002930000 2088460    30853    11642   286720        0           984 perl-fcgi-pm
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2088217] 1002930000 2088217   641322     5025   937984        0           984 httpd
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2088211] 1002930000 2088211   690490     5537  1007616        0           984 httpd
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2088210] 1002930000 2088210    65311     1015   540672        0           984 httpd
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2088209] 1002930000 2088209    65400     1015   536576        0           984 httpd
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2088208] 1002930000 2088208     5800      382    90112        0           984 cat
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2088207] 1002930000 2088207     5800      354    94208        0           984 cat
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2088177] 1002930000 2088177    65669     3329   561152        0           984 httpd
Jun 23 21:50:13 ip-10-0-138-48 kernel: [2088164]     0 2088164    35965      600   159744        0         -1000 conmon
Jun 23 21:50:13 ip-10-0-138-48 kernel: [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
Jun 23 21:50:13 ip-10-0-138-48 kernel: Tasks state (memory values in pages):


There seems to be lack of memory inside of a cgroup and I am struggling to see a relation with OVS.

Perhaps with IPFIX enabled in OVS some web dashboard is consuming more memory? But it doesn't make sense
to have kernel problems in the swap context with just userspace issues.

Can you confirm that the only thing changing is enabling IPFIX in OVS?

Thanks,
fbl

Could you also please elaborate on what this means "we have seen this issue multiple times, when comparing against ebpf agent of Network Observability" ?
Thanks,
fbl

(In reply to Flavio Leitner from comment #9)
> Could you also please elaborate on what this means "we have seen this issue
> multiple times, when comparing against ebpf agent of Network Observability" ?
> Thanks,
> fbl

We run similar test by using ebpf agent for flow exports which doesn't not involve OVS where we don't see such issues when flow sampling of 1 is configured, however we run into this issue consistently when IPFIX flow exports are enabled with OVS with sampling of 1. 


> Can you confirm that the only thing changing is enabling IPFIX in OVS?

Yes, at least we're just changing that piece as part of this test from our end for OVS. 

We have these cluster nodes still up if you want to investigate kernel logs by logging onto machine if that helps. We saw multiple nodes going into NotReady state.

I've taken over this BZ from Flavio for now, as he is on PTO. I looked at the logs, and even before the out-of-memory errors I see this:

Jun 30 12:11:42 ip-10-0-138-48 systemd-coredump[1160132]: Process 1158286 (systemd-journal) of user 0 dumped core.
Jun 30 11:30:00 ip-10-0-138-48 systemd-coredump[1158182]: Process 932 (systemd-journal) of user 0 dumped core.
Jun 29 23:30:17 ip-10-0-138-48 systemd-coredump[601122]: Process 600593 (httpd) of user 1002260000 dumped core.
Jun 29 17:24:29 ip-10-0-138-48 systemd-coredump[303907]: Process 303810 (httpd) of user 1004120000 dumped core.
Jun 29 13:45:37 ip-10-0-138-48 systemd-coredump[124760]: Process 124631 (httpd) of user 1000910000 dumped core.
Jun 29 05:21:42 ip-10-0-138-48 systemd-coredump[3902785]: Process 3902249 (httpd) of user 1004490000 dumped core.
Jun 28 23:28:23 ip-10-0-138-48 systemd-coredump[3607138]: Process 3606998 (httpd) of user 1002310000 dumped core.
Jun 28 20:52:09 ip-10-0-138-48 systemd-coredump[3477596]: Process 3477444 (httpd) of user 1006790000 dumped core.
Jun 24 10:05:28 ip-10-0-138-48 systemd-coredump[2842075]: Process 2841543 (httpd) of user 1002360000 dumped core.
Jun 24 09:26:09 ip-10-0-138-48 systemd-coredump[2807437]: Process 2806912 (httpd) of user 1001590000 dumped core.
Jun 24 09:12:26 ip-10-0-138-48 systemd-coredump[2796247]: Process 2794179 (httpd) of user 1001350000 dumped core.
Jun 24 02:59:13 ip-10-0-138-48 systemd-coredump[2453139]: Process 2452050 (httpd) of user 1008570000 dumped core.
Jun 24 02:54:06 ip-10-0-138-48 systemd-coredump[2447645]: Process 2447496 (httpd) of user 1008350000 dumped core.
Jun 23 23:29:51 ip-10-0-138-48 systemd-coredump[2227495]: Process 2227365 (httpd) of user 1002260000 dumped core.
Jun 23 23:08:05 ip-10-0-138-48 systemd-coredump[2187558]: Process 2187393 (httpd) of user 1001540000 dumped core.
Jun 23 18:22:00 ip-10-0-138-48 systemd-coredump[1790317]: Process 1789617 (httpd) of user 1011880000 dumped core.
Jun 23 06:27:31 ip-10-0-138-48 systemd-coredump[829334]: Process 828295 (httpd) of user 1003410000 dumped core.
Jun 23 06:27:31 ip-10-0-138-48 systemd-coredump[829335]: Process 828289 (httpd) of user 1003410000 dumped core.
Jun 23 03:42:45 ip-10-0-138-48 systemd-coredump[635940]: Process 635938 (httpd) of user 1004920000 dumped core.
Jun 23 01:48:46 ip-10-0-138-48 systemd-coredump[524159]: Process 523675 (httpd) of user 1002260000 dumped core.
Jun 23 01:14:34 ip-10-0-138-48 systemd-coredump[491839]: Process 491657 (httpd) of user 1001300000 dumped core.
Jun 22 21:29:07 ip-10-0-138-48 systemd-coredump[268601]: Process 268428 (httpd) of user 1003970000 dumped core.

It might not be related, but might be worth investigating.

However looking at the main problem, it looks like the system is running out of memory, so can you please do some additional tests to figure out which process(es) start accumulating memory after you enable IPFIX?

@echaudro is there a tool to attach to these nodes to collect resource utilization information for them? 

Running something like top is not convenient and doesn't give us information when we want to look for trends over a period of time. Since these tests are run with OCP, we have a way to collect information for container processes from Prometheus but I am not sure what's best way to collect the information for processes on nodes. Could you please share if you are of aware of any? Thanks!

(In reply to Mehul Modi from comment #12)
> @echaudro is there a tool to attach to these nodes to collect
> resource utilization information for them? 
> 
> Running something like top is not convenient and doesn't give us information
> when we want to look for trends over a period of time. Since these tests are
> run with OCP, we have a way to collect information for container processes
> from Prometheus but I am not sure what's best way to collect the information
> for processes on nodes. Could you please share if you are of aware of any?
> Thanks!

I'm not an OCP expert, so not aware of any fancy tools to do this. I guess these might also fail, as they would suffer from the same memory depletion... So I would just go for something old school and on all the nodes. For example, the following will capture memory stats for an hour:

 for i in {1..720}; do top -b -o +%MEM -n 1; cat /proc/meminfo; sleep 5; done | tee mem_node_x.txt


I was assuming this will happen shortly after enabling IPFIX, or is this not true?

(In reply to Eelco Chaudron from comment #13)
> (In reply to Mehul Modi from comment #12)
> > @echaudro is there a tool to attach to these nodes to collect
> > resource utilization information for them? 
> > 
> > Running something like top is not convenient and doesn't give us information
> > when we want to look for trends over a period of time. Since these tests are
> > run with OCP, we have a way to collect information for container processes
> > from Prometheus but I am not sure what's best way to collect the information
> > for processes on nodes. Could you please share if you are of aware of any?
> > Thanks!
> 
> I'm not an OCP expert, so not aware of any fancy tools to do this. I guess
> these might also fail, as they would suffer from the same memory
> depletion... So I would just go for something old school and on all the
> nodes. For example, the following will capture memory stats for an hour:
> 
>  for i in {1..720}; do top -b -o +%MEM -n 1; cat /proc/meminfo; sleep 5;
> done | tee mem_node_x.txt

I'll try this out, I am currently running on 3 master nodes. 


> I was assuming this will happen shortly after enabling IPFIX, or is this not
> true?

IPFIX can still be enabled with higher sampling rates without any issues, we had seen this behavior when sampling of 1 with IPFIX is enabled and let it run for few hours or couple of days. This is with: 4.11.0-0.nightly-2022-06-22-015220 and openvswitch2.17-2.17.0-22.el8fdp.x86_64

We had seen immediate networking degradation in newer OCP nightlies when IPFIX is enabled with sampling of 1 on weaker machines, for this a separate bug has been field: https://bugzilla.redhat.com/show_bug.cgi?id=2104957. It's unclear whether these both issues are stemming from the same source.

Just a random thought... How much traffic are you injecting, as you might easily overload the system as you sent every packet to IPFIX (maybe even IPFIX?), and also there is the potential loop issue!

Not sure how you set things up, but every packet you sent through IPFix is also a networking packet, so if these packets also travel through OVS they will also be copied and (re-send) through IPFix creating a loop, i.e. a single packet will live on forever...

Hi Eelco,
On the potential loop effect, there should be some mechanisms to prevent it. There should be two levels of aggregation in the IPFIX format that prevent a 1-to-1 ratio of observed packets versus produced packets:

- First level, a single flow can represent multiple packets. A flow has a packets counter associated with (cf https://datatracker.ietf.org/doc/html/rfc7011#appendix-A.3 ), so multiple observed packets add up.
- Second level, the IPFIX packets themselves are an aggregation of flows, they are sent as "flow sets", not as individual flows. (cf https://datatracker.ietf.org/doc/html/rfc7011#section-3 ).

In OVS there are two parameters to control the flows aggregation: cacheMaxFlows and cacheActiveTimeout. The defaults that we use in NetObserv are:
    cacheActiveTimeout: 60s
    cacheMaxFlows: 100
I don't think Mehul changed these defaults in the tests, can you confirm Mehul?

So if everything works correctly in the IPFIX aggregations in OVS, I don't think the extra traffic caused by IPFIX could be the cause.

BTW, it could be interesting to see if the problem can be mitigated by raising the amount of "cacheMaxFlows".
Mehul, in the eBPF agent we've set default cachemaxflows to 1000. We could try the same for ovs/ipfix and see if it improves stability.

(In reply to Joel Takvorian from comment #16)
> Hi Eelco,
> On the potential loop effect, there should be some mechanisms to prevent it.
> There should be two levels of aggregation in the IPFIX format that prevent a
> 1-to-1 ratio of observed packets versus produced packets:
> 
> - First level, a single flow can represent multiple packets. A flow has a
> packets counter associated with (cf
> https://datatracker.ietf.org/doc/html/rfc7011#appendix-A.3 ), so multiple
> observed packets add up.
> - Second level, the IPFIX packets themselves are an aggregation of flows,
> they are sent as "flow sets", not as individual flows. (cf
> https://datatracker.ietf.org/doc/html/rfc7011#section-3 ).
> 
> In OVS there are two parameters to control the flows aggregation:
> cacheMaxFlows and cacheActiveTimeout. The defaults that we use in NetObserv
> are:
>     cacheActiveTimeout: 60s
>     cacheMaxFlows: 100
> I don't think Mehul changed these defaults in the tests, can you confirm
> Mehul?
> 
> So if everything works correctly in the IPFIX aggregations in OVS, I don't
> think the extra traffic caused by IPFIX could be the cause.

Well, but still we can create a record for the IPFIX packet, and with IPFIX set to 1, we still will send every packet (batched or not).

To be more specific, how is an IPFIX packet sent to the IFPIX agent? Will it flow through the same OVN/OVS infrastructure, and if so will it be sampled by IPFIX, it should not be.

(In reply to Eelco Chaudron from comment #18)
> Well, but still we can create a record for the IPFIX packet, and with IPFIX
> set to 1, we still will send every packet (batched or not).
> 
> To be more specific, how is an IPFIX packet sent to the IFPIX agent? Will it
> flow through the same OVN/OVS infrastructure
> and if so will it be sampled
> by IPFIX, it should not be.

Yes, there is extra traffic caused by observing the IPFIX traffic itself. It uses the same ovn/ovs infrastructure than common cluster traffic. But I don't think it has to be ignored : it's part of the infrastructure traffic that users may want to observe, too. I agree it would raise a technical problem if there was no aggregation (like it's the case with other protocols such as sFlow), but with IPFIX, the aggregations should make it safe.

As Mehul said before, we also have an alternative monitoring method based on an eBPF agent, that works fine even with 1:1 sampling. The situation is exactly the same, traffic generated by the agent is also captured / self-monitored. We would expect it can work with OVS too (although with higher CPU load). As I mentionned, maybe the problem is we are too relaxed on the aggregation parameters. That's something to look into. But it should not defeat the idea of self-monitoring flows imho.

As discussed on slack, overnight one worker node went into NotReady state since I was not collecting memory stats there. I did reboot the node and collected journalctl and ovs-vswitchd logs here: https://drive.google.com/drive/folders/1blMbzOswbQ5ZuDKNNjF50kkIvKKg1PYa?usp=sharing


I did see below lines in ovs-vswitchd.log, not sure if these are any indicators:

2022-07-12T10:12:48.834Z|00001|collectors(handler2)|WARN|Dropped 16 log messages in last 418 seconds (most recently, 418 seconds ago) due to excessive rate
2022-07-12T10:12:48.834Z|00002|collectors(handler2)|WARN|10.0.212.189:53364<->172.30.151.103:2055: sending to collector failed (Network is unreachable)
2022-07-12T10:12:48.834Z|00003|collectors(handler2)|WARN|10.0.212.189:53364<->172.30.151.103:2055: sending to collector failed (Network is unreachable)
2022-07-12T10:12:48.834Z|00004|collectors(handler2)|WARN|10.0.212.189:53364<->172.30.151.103:2055: sending to collector failed (Network is unreachable)
2022-07-12T10:12:48.834Z|00005|collectors(handler2)|WARN|10.0.212.189:53364<->172.30.151.103:2055: sending to collector failed (Network is unreachable)
2022-07-12T10:12:48.834Z|00006|collectors(handler2)|WARN|10.0.212.189:53364<->172.30.151.103:2055: sending to collector failed (Network is unreachable)
2022-07-12T10:13:50.000Z|00001|collectors(handler9)|WARN|Dropped 2239 log messages in last 61 seconds (most recently, 1 seconds ago) due to excessive rate
2022-07-12T10:13:50.000Z|00002|collectors(handler9)|WARN|10.0.212.189:53364<->172.30.151.103:2055: sending to collector failed (Network is unreachable)
2022-07-12T10:14:50.415Z|00007|collectors(handler2)|WARN|Dropped 1857 log messages in last 61 seconds (most recently, 2 seconds ago) due to excessive rate
2022-07-12T10:14:50.415Z|00008|collectors(handler2)|WARN|10.0.212.189:53364<->172.30.151.103:2055: sending to collector failed (Network is unreachable)
2022-07-12T10:16:25.917Z|00336|collectors|WARN|Dropped 749 log messages in last 95 seconds (most recently, 40 seconds ago) due to excessive rate
2022-07-12T10:16:25.917Z|00337|collectors|WARN|10.0.212.189:53364<->172.30.151.103:2055: sending to collector failed (Network is unreachable)
2022-07-12T10:17:28.112Z|00002|collectors(handler7)|WARN|Dropped 119 log messages in last 62 seconds (most recently, 42 seconds ago) due to excessive rate
2022-07-12T10:17:28.112Z|00003|collectors(handler7)|WARN|10.0.212.189:53364<->172.30.151.103:2055: sending to collector failed (Network is unreachable)
2022-07-12T10:17:33.557Z|00338|rconn|ERR|br-int<->unix#603: no response to inactivity probe after 60 seconds, disconnecting
2022-07-12T10:17:53.790Z|00004|collectors(handler7)|WARN|Dropped 11 log messages in last 26 seconds (most recently, 22 seconds ago) due to excessive rate
2022-07-12T10:17:53.790Z|00005|collectors(handler7)|WARN|10.0.212.189:53364<->172.30.151.103:2055: sending to collector failed (Network is unreachable)

(In reply to Mehul Modi from comment #21)

> 2022-07-12T10:17:53.790Z|00005|collectors(handler7)|WARN|10.0.212.189:53364<->172.30.151.103:2055: sending to collector failed (Network is unreachable)

Looked at the OVS logs, and nothing stands out, other than the ones you mention. So maybe you can see why the kernel tells us that the 172.30.151.103 network is unreachable?


From journal log it goes wrong around these entries, but no idea why (guess memory, CPU resources):

Jul 12 02:50:19 ip-10-0-212-189 hyperkube[2073]: I0712 02:50:19.654096    2073 prober.go:121] "Probe failed" probeType="Liveness" pod="openshift-cluster-csi-drivers/aws-ebs-csi-driver-node-qbmkn" podUID=71e96e7d-68ad-454a-9801-b252f3b5fe3c containerName="csi-driver" probeResult=failure output="Get \"http://10.0.212.189:10300/healthz\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)"
Jul 12 02:50:19 ip-10-0-212-189 hyperkube[2073]: I0712 02:50:19.466313    2073 patch_prober.go:29] interesting pod/aws-ebs-csi-driver-node-qbmkn container/csi-driver namespace/openshift-cluster-csi-drivers: Liveness probe status=failure output="Get \"http://10.0.212.189:10300/healthz\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)" start-of-body=
Jul 12 02:50:14 ip-10-0-212-189 ovs-vswitchd[1295]: ovs|233973|connmgr|INFO|br-ex<->unix#968784: 2 flow_mods in the last 0 s (2 adds)

I can't match the OVS time stamp to the journal ones, as they seem missing any 10:xx entries. Let's wait for the memory logs.

Yesterday one of the nodes has gone into NotReady state, looking at the top info which was being collected at 30 seconds interval,  at the end CPU usage for prometheus had spiked to 112% and ovs-vswitchd to 25% on this node: Full memory usage data for this node here: https://drive.google.com/file/d/1HfxgK2cHImL8L_ttdgG6UroebXOTkPL2/view 

After rebooting this node since yesterday, I had checked this morning all nodes were up and running normally.

Currently, my cluster has been terminated since it has been running quite a few weeks now. I'll bring up another cluster to start the test and collecting data.

(In reply to Mehul Modi from comment #23)

> https://drive.google.com/file/d/1HfxgK2cHImL8L_ttdgG6UroebXOTkPL2/view 

I had a quick look at the data, and nothing stands out. The higher CPU for OVS makes sense as it gets a lot of upcalls, i.e., a copy of each packet from the kernel which it needs to batch and forward to the IPFIX receiver, I guess in your case Prometheus.

>  forward to the IPFIX receiver, I guess in your case Prometheus.

no, IPFIX flows are not received by Prometheus we have separate pod flowlogs-pipeline running for that, so Prometheus spike is unexplained here.

Added more data for another node that went into NotReady this morning: https://drive.google.com/drive/folders/1lSrjBci_j0_QpBlSntY7IaEj_6k9LWn1 , couldn't spot any abnormalities here except towards the end (presumably around Node went into that NotReady state) most of the node memory was utilized.

(In reply to Mehul Modi from comment #26)
> Added more data for another node that went into NotReady this morning:
> https://drive.google.com/drive/folders/1lSrjBci_j0_QpBlSntY7IaEj_6k9LWn1 ,
> couldn't spot any abnormalities here except towards the end (presumably
> around Node went into that NotReady state) most of the node memory was
> utilized.

Was there a oom kill in this NotReady event, would be good to identify who owned memory when that happened.

When discussing this with Mike, who will be taking over this BZ during my PTO, we noticed a case where we would leak the skb when the userspace buffer is full.

Here is the code path:

  do_execute_actions()
     output_userspace()
       ovs_dp_upcall()

The problem is that in do_execute_actions the return value is not used.

1276  		case OVS_ACTION_ATTR_USERSPACE:
1277  			output_userspace(dp, skb, key, a, attr,
1278  						     len, OVS_CB(skb)->cutlen);
1279  			OVS_CB(skb)->cutlen = 0;
1280  			break;

This should probably change to:

1277  			ret = output_userspace(dp, skb, key, a, attr,
1278  				         	     len, OVS_CB(skb)->cutlen);


Mike will try to replicate this and make a test kernel.

Fortunately (or unfortunately, depending on the perspective) the output_userspace() code path doesn't appear to be a memory leak, as all code paths in do_execute_actions() eventually end in consume_skb(). The only thing to verify in that thread is if we're properly recording errors in the dropped packet counter.

I set up a very simple environment to see if I can reproduce it with all external factors removed. I'm using ncat to create new flows on semi-random ips/ports, pushing this all through a vxlan terminated bridge, and forwarding the ipfix output to /dev/null via ncat. So in this VM the only thing that should be allocating memory is openvswitch.

Will return in a few days to see if anything ran out of memory.

After leaving the above experiment running for about a week, there was no sign of a memory leak in OVS or the kernel with IPfix on. I then tried a quick test where I sent the IPFIX through a vxlan tunnel that OVS was managing. This caused a spike in OVS cpu usage but still no increase in memory usage

Could you please dump the IPFIX configurations? I would like to confirm what the cache size is set as.

> ovs-vsctl list ipfix

Do we know how much data OVS vs ebpf is generating?

> ovs-vsctl list ipfix

[root@ip-10-0-137-65 ~]# /usr/bin/ovs-vsctl  list ipfix
_uuid               : 3275bc5a-d1d6-4ca0-b07c-55dc04819db4
cache_active_timeout: 60
cache_max_flows     : 100
external_ids        : {}
obs_domain_id       : []
obs_point_id        : []
other_config        : {}
sampling            : 1
targets             : ["172.30.165.162:2055"]
[root@ip-10-0-137-65 ~]#

I was able to replicate it. With wire-speed traffic running this is my laptop after two minutes:

  24785376 24785376 100%    0.50K 774543       32  12392688K kmalloc-512"

I'm sending traffic on ingress at wire speed (40G XL710), fixed IP/UDP traffic 68 bytes min packet size to broadcast mac.


- My setup:

 xena [2,0] ---> [enp5s0f1] ND65 [enp5s0f0] ---> [2,1] xena
                              |                         ip = 1.1.1.100/24
                              | net_ns IP = 1.1.1.200
                             con0


- This is my host configuration:

ovs-vsctl del-br br0
ovs-vsctl add-br br0
ovs-vsctl add-port br0 enp5s0f1
ovs-vsctl add-port br0 enp5s0f0
ovs-vsctl add-port br0 gen0 -- \
  set interface gen0 type=geneve options:remote_ip=1.1.1.100 options:key=123

ip link set dev br0 up
ip addr add 1.1.1.1/24 dev br0

ovs-ofctl del-flows br0
ovs-ofctl add-flow br0 "priority=100,table=0,actions=NORMAL"
ovs-ofctl add-flow br0 "priority=200,in_port=enp5s0f1,action:output=gen0"


ovs-vsctl clear Bridge br0 ipfix
ovs-vsctl -- set Bridge br0 ipfix=@i -- \
  --id=@i create IPFIX targets=\"1.1.1.200:4739\" \
    obs_domain_id=123  obs_point_id=456 cache_active_timeout=10 \
    cache_max_flows=10 sampling=1 \
    other_config:enable-tunnel-sampling=true

ip link add collector type veth peer name col0
ip netns add ns_col
ip link set col0 netns  ns_col

ip -n ns_col link set dev lo up
ip -n ns_col link set dev col0 up

ip link set dev collector up
ovs-vsctl add-port br0 collector

ip -n ns_col address add 1.1.1.200/24 dev col0


- Start the fake collector in the NS:

  ip netns exec ns_col nc -l 4739 -u | pv | hexdump


- Now start traffic at wire speed into enp5s0f1


Good luck...

I was finally able to reproduce this issue in my VM by further downgrading my kernel. 

This issue is fixed in kernel-4.18.0-381.el8.x86_64 via https://bugzilla.redhat.com/show_bug.cgi?id=2068355

(In reply to Michael Pattrick from comment #34)
> I was finally able to reproduce this issue in my VM by further downgrading
> my kernel. 
> 
> This issue is fixed in kernel-4.18.0-381.el8.x86_64 via
> https://bugzilla.redhat.com/show_bug.cgi?id=2068355

What kernel version(s) do we need this fixed in? If we know we can ask this to be backported to the specific Z stream.

(In reply to Eelco Chaudron from comment #35)
> (In reply to Michael Pattrick from comment #34)
> > I was finally able to reproduce this issue in my VM by further downgrading
> > my kernel. 
> > 
> > This issue is fixed in kernel-4.18.0-381.el8.x86_64 via
> > https://bugzilla.redhat.com/show_bug.cgi?id=2068355
> 
> What kernel version(s) do we need this fixed in? If we know we can ask this
> to be backported to the specific Z stream.

8.6.z at least.

(In reply to Dan Williams from comment #36)
> (In reply to Eelco Chaudron from comment #35)
> > (In reply to Michael Pattrick from comment #34)
> > > I was finally able to reproduce this issue in my VM by further downgrading
> > > my kernel. 
> > > 
> > > This issue is fixed in kernel-4.18.0-381.el8.x86_64 via
> > > https://bugzilla.redhat.com/show_bug.cgi?id=2068355
> > 
> > What kernel version(s) do we need this fixed in? If we know we can ask this
> > to be backported to the specific Z stream.
> 
> 8.6.z at least.

Ok, then we are good, as BZ2068355 has ZStream Target Release 8.4

Should be resolved with https://access.redhat.com/errata/RHSA-2022:7683