Selected must-gather: /home/surya/Downloads/bug-2084062/must-gather.local.5036870898416027574/quay-io-openshift-release-dev-ocp-v4-0-art-dev-sha256* Projects: 61 API URL: ['https://api.qili-aws-migration.qe.devcluster.openshift.com:6443'] Platform: ['AWS'] Cluster ID: ['9743a256-1b8f-4e61-9974-e11ddcef75d0'] Desired Version: ['4.11.0-0.nightly-2022-06-15-222801'] Debugging notes: Investigating MG in https://bugzilla.redhat.com/show_bug.cgi?id=2084062#c23 18m Warning FailedCreatePodSandBox pod/http-perf-100-5d54c7bcd5-8mbmf Failed to create pod sandbox: rpc error: code = Unknown desc = failed to create pod network sandbox k8s_http-perf-100-5d54c7bcd5-8mbmf_http-scale-reencrypt_bac2d32a-9a5b-425c-a37b-51b203ef596b_0(49afe993dd56588aca9c189dec763c72a697622250ce1a335359f94a3d3a8f93): error adding pod http-scale-reencrypt_http-perf-100-5d54c7bcd5-8mbmf to CNI network "multus-cni-network": plugin type="multus" name="multus-cni-network" failed (add): [http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf/bac2d32a-9a5b-425c-a37b-51b203ef596b:ovn-kubernetes]: error adding container to network "ovn-kubernetes": CNI request failed with status 400: '[http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf 49afe993dd56588aca9c189dec763c72a697622250ce1a335359f94a3d3a8f93] [http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf 49afe993dd56588aca9c189dec763c72a697622250ce1a335359f94a3d3a8f93] failed to configure pod interface: timed out waiting for OVS port binding (ovn-installed) for 0a:58:0a:81:38:29 [10.129.56.41/23]... ovnkube-master logs: 2022-06-20T03:50:09.836846395+00:00 stderr F I0620 03:50:09.836840 1 pods.go:364] [http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf] creating logical port for pod on switch ip-10-0-202-130.us-east-2.compute.internal 2022-06-20T03:50:09.836952110+00:00 stderr F I0620 03:50:09.836936 1 kube.go:73] Setting annotations map[k8s.ovn.org/pod-networks:{"default":{"ip_addresses":["10.129.56.41/23"],"mac_address":"0a:58:0a:81:38:29","gateway_ips":["10.129.56.1"],"ip_address":"10.129.56.41/23","gateway_ip":"10.129.56.1"}}] on pod http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf 2022-06-20T03:50:09.872333792+00:00 stderr F I0620 03:50:09.872312 1 pods.go:353] [http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf] addLogicalPort took 35.473456ms, libovsdb time 5.414785ms, annotation time: 29.413274ms ovnkube-node logs: 2022-06-20T03:50:10.317978358Z I0620 03:50:10.317919 3468 cni.go:227] [http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf 49afe993dd56588aca9c189dec763c72a697622250ce1a335359f94a3d3a8f93] ADD starting CNI request [http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf 49afe993dd56588aca9c189dec763c72a697622250ce1a335359f94a3d3a8f93] 2022-06-20T03:50:10.339690697Z I0620 03:50:10.339655 3468 helper_linux.go:249] ConfigureOVS: namespace: http-scale-reencrypt, podName: http-perf-100-5d54c7bcd5-8mbmf 2022-06-20T03:52:10.517428559Z W0620 03:52:10.517391 3468 helper_linux.go:309] [http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf 49afe993dd56588aca9c189dec763c72a697622250ce1a335359f94a3d3a8f93] pod uid bac2d32a-9a5b-425c-a37b-51b203ef596b: timed out waiting for OVS port binding (ovn-installed) for 0a:58:0a:81:38:29 [10.129.56.41/23] 2022-06-20T03:52:10.691101846Z I0620 03:52:10.691049 3468 cni.go:248] [http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf 49afe993dd56588aca9c189dec763c72a697622250ce1a335359f94a3d3a8f93] ADD finished CNI request [http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf 49afe993dd56588aca9c189dec763c72a697622250ce1a335359f94a3d3a8f93], result "", err failed to configure pod interface: timed out waiting for OVS port binding (ovn-installed) for 0a:58:0a:81:38:29 [10.129.56.41/23] 2022-06-20T03:52:10.813455713Z I0620 03:52:10.813411 3468 cni.go:227] [http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf 49afe993dd56588aca9c189dec763c72a697622250ce1a335359f94a3d3a8f93] DEL starting CNI request [http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf 49afe993dd56588aca9c189dec763c72a697622250ce1a335359f94a3d3a8f93] 2022-06-20T03:52:10.828542679Z W0620 03:52:10.828516 3468 helper_linux.go:490] Failed to delete pod "http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf" interface 49afe993dd56588: failed to lookup link 49afe993dd56588: Link not found 2022-06-20T03:52:10.850862036Z I0620 03:52:10.850818 3468 cni.go:248] [http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf 49afe993dd56588aca9c189dec763c72a697622250ce1a335359f94a3d3a8f93] DEL finished CNI request [http-scale-reencrypt/http-perf-100-5d54c7bcd5-8mbmf 49afe993dd56588aca9c189dec763c72a697622250ce1a335359f94a3d3a8f93], result "{\"dns\":{}}", err <nil> ovn-controller logs: NO port binding happened in OVN for this pod! :/ between 03:50:10.339690697Z and 03:52:10.517428559Z: 2022-06-20T03:50:01.071887679Z 2022-06-20T03:50:01.071Z|00321|lflow_cache|INFO|Detected cache inactivity (last active 30002 ms ago): trimming cache 2022-06-20T03:50:23.790863656Z 2022-06-20T03:50:23.790Z|00322|binding|INFO|Claiming lport http-scale-reencrypt_http-perf-28-6f8668bd6b-s7pnb for this chassis. 2022-06-20T03:50:23.790863656Z 2022-06-20T03:50:23.790Z|00323|binding|INFO|http-scale-reencrypt_http-perf-28-6f8668bd6b-s7pnb: Claiming 0a:58:0a:81:38:27 10.129.56.39 2022-06-20T03:50:23.790972401Z 2022-06-20T03:50:23.790Z|00324|binding|INFO|Claiming lport http-scale-reencrypt_http-perf-35-6d74f89556-kvffk for this chassis. 2022-06-20T03:50:23.790972401Z 2022-06-20T03:50:23.790Z|00325|binding|INFO|http-scale-reencrypt_http-perf-35-6d74f89556-kvffk: Claiming 0a:58:0a:81:38:26 10.129.56.38 2022-06-20T03:50:24.090772932Z 2022-06-20T03:50:24.090Z|00326|timeval|WARN|Unreasonably long 2174ms poll interval (2098ms user, 50ms system) 2022-06-20T03:50:24.090772932Z 2022-06-20T03:50:24.090Z|00327|timeval|WARN|faults: 28801 minor, 0 major 2022-06-20T03:50:24.090772932Z 2022-06-20T03:50:24.090Z|00328|timeval|WARN|context switches: 8 voluntary, 11 involuntary 2022-06-20T03:50:24.112735130Z 2022-06-20T03:50:24.112Z|00329|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour, hash=7fc5f780: 2022-06-20T03:50:24.112735130Z 2022-06-20T03:50:24.112Z|00330|coverage|INFO|lflow_run 0.0/sec 0.000/sec 0.0156/sec total: 56 2022-06-20T03:50:24.112735130Z 2022-06-20T03:50:24.112Z|00331|coverage|INFO|consider_logical_flow 0.0/sec 170.667/sec 953.3231/sec total: 3508124 2022-06-20T03:50:24.112735130Z 2022-06-20T03:50:24.112Z|00332|coverage|INFO|lflow_cache_add_expr 0.0/sec 0.000/sec 1.4525/sec total: 5310 2022-06-20T03:50:24.112735130Z 2022-06-20T03:50:24.112Z|00333|coverage|INFO|lflow_cache_add_matches 0.0/sec 2.667/sec 6.3044/sec total: 23884 2022-06-20T03:50:24.112735130Z 2022-06-20T03:50:24.112Z|00334|coverage|INFO|lflow_cache_free_expr 0.0/sec 0.000/sec 0.1956/sec total: 704 2022-06-20T03:50:24.112735130Z 2022-06-20T03:50:24.112Z|00335|coverage|INFO|lflow_cache_free_matches 0.0/sec 2.667/sec 2.4769/sec total: 8997 2022-06-20T03:50:24.112735130Z 2022-06-20T03:50:24.112Z|00336|coverage|INFO|lflow_cache_add 0.0/sec 2.667/sec 7.7569/sec total: 29194 2022-06-20T03:50:24.112735130Z 2022-06-20T03:50:24.112Z|00337|coverage|INFO|lflow_cache_hit 0.0/sec 2.667/sec 90.7181/sec total: 326665 2022-06-20T03:50:24.112735130Z 2022-06-20T03:50:24.112Z|00338|coverage|INFO|lflow_cache_miss 0.0/sec 341.333/sec 135.2019/sec total: 498156 2022-06-20T03:50:24.112735130Z 2022-06-20T03:50:24.112Z|00339|coverage|INFO|lflow_cache_delete 0.0/sec 2.667/sec 2.6725/sec total: 9701 2022-06-20T03:50:24.112735130Z 2022-06-20T03:50:24.112Z|00340|coverage|INFO|lflow_cache_trim 0.0/sec 0.033/sec 0.0017/sec total: 6 2022-06-20T03:50:24.112735130Z 2022-06-20T03:50:24.112Z|00341|coverage|INFO|pinctrl_notify_main_thread 0.0/sec 0.017/sec 0.0064/sec total: 23 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00342|coverage|INFO|pinctrl_total_pin_pkts 0.0/sec 0.017/sec 0.0108/sec total: 39 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00343|coverage|INFO|physical_run 0.0/sec 0.000/sec 0.0169/sec total: 61 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00344|coverage|INFO|flow_extract 0.0/sec 0.017/sec 0.0108/sec total: 39 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00345|coverage|INFO|miniflow_malloc 0.0/sec 9.400/sec 167.6742/sec total: 606952 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00346|coverage|INFO|hmap_pathological 3.6/sec 9.183/sec 18.5383/sec total: 67856 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00347|coverage|INFO|hmap_expand 136.8/sec 588.600/sec 871.7269/sec total: 3293715 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00348|coverage|INFO|txn_unchanged 1.4/sec 3.450/sec 4.9625/sec total: 18294 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00349|coverage|INFO|txn_incomplete 0.0/sec 0.017/sec 0.1986/sec total: 716 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00350|coverage|INFO|txn_success 0.0/sec 0.017/sec 0.0436/sec total: 157 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00351|coverage|INFO|poll_create_node 19.2/sec 38.567/sec 55.1614/sec total: 202889 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00352|coverage|INFO|poll_zero_timeout 0.0/sec 0.467/sec 0.7553/sec total: 2928 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00353|coverage|INFO|rconn_queued 0.0/sec 8.167/sec 15.3378/sec total: 56980 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00354|coverage|INFO|rconn_sent 0.0/sec 8.167/sec 15.3378/sec total: 55455 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00355|coverage|INFO|seq_change 9.0/sec 16.250/sec 24.9778/sec total: 91752 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00356|coverage|INFO|pstream_open 0.0/sec 0.000/sec 0.0003/sec total: 1 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00357|coverage|INFO|stream_open 0.0/sec 0.000/sec 0.0014/sec total: 5 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00358|coverage|INFO|unixctl_received 0.0/sec 0.000/sec 0.0036/sec total: 13 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00359|coverage|INFO|unixctl_replied 0.0/sec 0.000/sec 0.0036/sec total: 13 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00360|coverage|INFO|util_xalloc 3158.4/sec 24218.833/sec 42125.6739/sec total: 160218859 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00361|coverage|INFO|vconn_open 0.0/sec 0.000/sec 0.0008/sec total: 3 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00362|coverage|INFO|vconn_received 0.4/sec 0.250/sec 0.6819/sec total: 2456 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00363|coverage|INFO|vconn_sent 0.0/sec 8.183/sec 15.3711/sec total: 55576 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00364|coverage|INFO|netlink_received 1.0/sec 0.350/sec 2.2506/sec total: 8108 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00365|coverage|INFO|netlink_recv_jumbo 0.4/sec 0.117/sec 0.7497/sec total: 2701 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00366|coverage|INFO|netlink_sent 1.0/sec 0.350/sec 2.2506/sec total: 8108 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00367|coverage|INFO|cmap_expand 0.0/sec 0.000/sec 0.0008/sec total: 3 2022-06-20T03:50:24.112788731Z 2022-06-20T03:50:24.112Z|00368|coverage|INFO|102 events never hit 2022-06-20T03:50:24.112819631Z 2022-06-20T03:50:24.112Z|00369|poll_loop|INFO|wakeup due to [POLLIN][POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (80% CPU usage) 2022-06-20T03:50:24.112828242Z 2022-06-20T03:50:24.112Z|00370|poll_loop|INFO|wakeup due to [POLLIN] on fd 19 (10.0.202.130:45906<->10.0.192.114:9642) at lib/stream-ssl.c:836 (80% CPU usage) 2022-06-20T03:50:24.135363710Z 2022-06-20T03:50:24.135Z|00371|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (80% CPU usage) 2022-06-20T03:50:24.137366333Z 2022-06-20T03:50:24.137Z|00372|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (80% CPU usage) 2022-06-20T03:50:24.139026683Z 2022-06-20T03:50:24.139Z|00373|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (80% CPU usage) 2022-06-20T03:50:24.140555538Z 2022-06-20T03:50:24.140Z|00374|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (80% CPU usage) 2022-06-20T03:50:24.142565911Z 2022-06-20T03:50:24.142Z|00375|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (80% CPU usage) 2022-06-20T03:50:24.144052583Z 2022-06-20T03:50:24.144Z|00376|poll_loop|INFO|wakeup due to 0-ms timeout at lib/rconn.c:543 (80% CPU usage) 2022-06-20T03:50:24.146561013Z 2022-06-20T03:50:24.146Z|00377|poll_loop|INFO|wakeup due to [POLLIN] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:157 (80% CPU usage) 2022-06-20T03:50:24.150147388Z 2022-06-20T03:50:24.150Z|00378|binding|INFO|Setting lport http-scale-reencrypt_http-perf-35-6d74f89556-kvffk ovn-installed in OVS 2022-06-20T03:50:24.150147388Z 2022-06-20T03:50:24.150Z|00379|binding|INFO|Setting lport http-scale-reencrypt_http-perf-28-6f8668bd6b-s7pnb ovn-installed in OVS 2022-06-20T03:50:24.151568542Z 2022-06-20T03:50:24.151Z|00380|poll_loop|INFO|wakeup due to [POLLIN] on fd 16 (<->/var/run/openvswitch/db.sock) at lib/stream-fd.c:157 (80% CPU usage) 2022-06-20T03:50:25.115785832Z 2022-06-20T03:50:25.115Z|00381|binding|INFO|Setting lport http-scale-reencrypt_http-perf-35-6d74f89556-kvffk up in Southbound 2022-06-20T03:50:25.115819006Z 2022-06-20T03:50:25.115Z|00382|binding|INFO|Setting lport http-scale-reencrypt_http-perf-28-6f8668bd6b-s7pnb up in Southbound 2022-06-20T03:50:54.009901327Z 2022-06-20T03:50:54.009Z|00383|lflow_cache|INFO|Detected cache inactivity (last active 30002 ms ago): trimming cache 2022-06-20T03:51:33.203211049Z 2022-06-20T03:51:33.203Z|00384|ovsdb_cs|INFO|ssl:10.0.192.114:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T03:51:33.204608814Z 2022-06-20T03:51:33.204Z|00385|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T03:51:33.204969288Z 2022-06-20T03:51:33.204Z|00386|reconnect|INFO|ssl:10.0.192.114:9642: connection attempt timed out 2022-06-20T03:51:33.206629330Z 2022-06-20T03:51:33.206Z|00387|reconnect|INFO|ssl:10.0.145.30:9642: connecting... 2022-06-20T03:51:33.240415726Z 2022-06-20T03:51:33.240Z|00388|reconnect|INFO|ssl:10.0.145.30:9642: connected 2022-06-20T03:51:33.862631040Z 2022-06-20T03:51:33.862Z|00389|inc_proc_eng|INFO|node: logical_flow_output, recompute (forced) took 606ms 2022-06-20T03:52:23.920469386Z 2022-06-20T03:52:23.920Z|00390|ovsdb_cs|INFO|ssl:10.0.145.30:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T03:51:33.204608814Z 2022-06-20T03:51:33.204Z|00385|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T03:51:33.204969288Z 2022-06-20T03:51:33.204Z|00386|reconnect|INFO|ssl:10.0.192.114:9642: connection attempt timed out 2022-06-20T03:51:33.206629330Z 2022-06-20T03:51:33.206Z|00387|reconnect|INFO|ssl:10.0.145.30:9642: connecting... 2022-06-20T03:51:33.240415726Z 2022-06-20T03:51:33.240Z|00388|reconnect|INFO|ssl:10.0.145.30:9642: connected 2022-06-20T03:51:33.862631040Z 2022-06-20T03:51:33.862Z|00389|inc_proc_eng|INFO|node: logical_flow_output, recompute (forced) took 606ms 2022-06-20T03:52:23.920469386Z 2022-06-20T03:52:23.920Z|00390|ovsdb_cs|INFO|ssl:10.0.145.30:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T03:52:23.921943677Z 2022-06-20T03:52:23.921Z|00391|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T03:52:23.922328876Z 2022-06-20T03:52:23.922Z|00392|reconnect|INFO|ssl:10.0.145.30:9642: connection attempt timed out 2022-06-20T03:52:23.924350787Z 2022-06-20T03:52:23.924Z|00393|reconnect|INFO|ssl:10.0.171.139:9642: connecting... 2022-06-20T03:52:24.171110484Z 2022-06-20T03:52:24.171Z|00394|reconnect|INFO|ssl:10.0.171.139:9642: connected 2022-06-20T03:52:24.769650442Z 2022-06-20T03:52:24.769Z|00395|inc_proc_eng|INFO|node: logical_flow_output, recompute (forced) took 585ms 2022-06-20T03:56:14.678756678Z 2022-06-20T03:56:14.678Z|00396|ovsdb_cs|INFO|ssl:10.0.171.139:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T03:56:14.680305386Z 2022-06-20T03:56:14.680Z|00397|reconnect|INFO|ssl:10.0.171.139:9642: connection attempt timed out 2022-06-20T03:56:14.681285204Z 2022-06-20T03:56:14.681Z|00398|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T03:56:14.682377730Z 2022-06-20T03:56:14.682Z|00399|reconnect|INFO|ssl:10.0.192.114:9642: connecting... 2022-06-20T03:56:15.683790831Z 2022-06-20T03:56:15.683Z|00400|reconnect|INFO|ssl:10.0.192.114:9642: connection attempt timed out 2022-06-20T03:56:15.685858381Z 2022-06-20T03:56:15.685Z|00401|reconnect|INFO|ssl:10.0.145.30:9642: connecting... 2022-06-20T03:56:15.900465475Z 2022-06-20T03:56:15.900Z|00402|reconnect|INFO|ssl:10.0.145.30:9642: connected 2022-06-20T03:56:16.479788858Z 2022-06-20T03:56:16.479Z|00403|inc_proc_eng|INFO|node: logical_flow_output, recompute (forced) took 564ms 2022-06-20T04:02:22.430828436Z 2022-06-20T04:02:22.430Z|00404|ovsdb_cs|INFO|ssl:10.0.145.30:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T04:02:22.432341415Z 2022-06-20T04:02:22.432Z|00405|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T04:02:22.432685559Z 2022-06-20T04:02:22.432Z|00406|reconnect|INFO|ssl:10.0.145.30:9642: connection attempt timed out 2022-06-20T04:02:22.434520379Z 2022-06-20T04:02:22.434Z|00407|reconnect|INFO|ssl:10.0.171.139:9642: connecting... 2022-06-20T04:02:22.453601673Z 2022-06-20T04:02:22.453Z|00408|reconnect|INFO|ssl:10.0.171.139:9642: connected 2022-06-20T04:02:23.000609291Z 2022-06-20T04:02:23.000Z|00409|inc_proc_eng|INFO|node: logical_flow_output, recompute (forced) took 531ms 2022-06-20T04:05:34.940718478Z 2022-06-20T04:05:34.940Z|00410|ovsdb_cs|INFO|ssl:10.0.171.139:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T04:05:34.942181084Z 2022-06-20T04:05:34.942Z|00411|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T04:05:34.942517888Z 2022-06-20T04:05:34.942Z|00412|reconnect|INFO|ssl:10.0.171.139:9642: connection attempt timed out 2022-06-20T04:05:34.944383109Z 2022-06-20T04:05:34.944Z|00413|reconnect|INFO|ssl:10.0.192.114:9642: connecting... 2022-06-20T04:05:34.959028618Z 2022-06-20T04:05:34.959Z|00414|reconnect|INFO|ssl:10.0.192.114:9642: connected 2022-06-20T04:05:35.526262905Z 2022-06-20T04:05:35.526Z|00415|inc_proc_eng|INFO|node: logical_flow_output, recompute (forced) took 548ms 2022-06-20T04:07:53.211998077Z 2022-06-20T04:07:53.211Z|00416|ovsdb_cs|INFO|ssl:10.0.192.114:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T04:07:53.213509504Z 2022-06-20T04:07:53.213Z|00417|reconnect|INFO|ssl:10.0.192.114:9642: connection attempt timed out 2022-06-20T04:07:53.214429011Z 2022-06-20T04:07:53.214Z|00418|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T04:07:53.215651425Z 2022-06-20T04:07:53.215Z|00419|reconnect|INFO|ssl:10.0.145.30:9642: connecting... 2022-06-20T04:07:54.217288240Z 2022-06-20T04:07:54.217Z|00420|reconnect|INFO|ssl:10.0.145.30:9642: connection attempt timed out 2022-06-20T04:07:54.220063237Z 2022-06-20T04:07:54.220Z|00421|reconnect|INFO|ssl:10.0.171.139:9642: connecting... 2022-06-20T04:07:55.221398734Z 2022-06-20T04:07:55.221Z|00422|reconnect|INFO|ssl:10.0.171.139:9642: connection attempt timed out 2022-06-20T04:07:55.223374738Z 2022-06-20T04:07:55.223Z|00423|reconnect|INFO|ssl:10.0.192.114:9642: connecting... 2022-06-20T04:07:55.232824084Z 2022-06-20T04:07:55.232Z|00424|reconnect|INFO|ssl:10.0.192.114:9642: connected 2022-06-20T04:07:55.235539685Z 2022-06-20T04:07:55.235Z|00425|ovsdb_cs|INFO|ssl:10.0.192.114:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T04:07:55.236161713Z 2022-06-20T04:07:55.236Z|00426|reconnect|INFO|ssl:10.0.192.114:9642: connection attempt timed out 2022-06-20T04:07:56.238524079Z 2022-06-20T04:07:56.238Z|00427|reconnect|INFO|ssl:10.0.145.30:9642: connecting... 2022-06-20T04:07:56.285968691Z 2022-06-20T04:07:56.285Z|00428|reconnect|INFO|ssl:10.0.145.30:9642: connected 2022-06-20T04:07:56.885439820Z 2022-06-20T04:07:56.885Z|00429|inc_proc_eng|INFO|node: logical_flow_output, recompute (forced) took 583ms 2022-06-20T04:13:35.478169954Z 2022-06-20T04:13:35.478Z|00430|ovsdb_cs|INFO|ssl:10.0.145.30:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T04:13:35.479558085Z 2022-06-20T04:13:35.479Z|00431|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T04:13:35.479886468Z 2022-06-20T04:13:35.479Z|00432|reconnect|INFO|ssl:10.0.145.30:9642: connection attempt timed out 2022-06-20T04:13:35.481760081Z 2022-06-20T04:13:35.481Z|00433|reconnect|INFO|ssl:10.0.171.139:9642: connecting... 2022-06-20T04:13:36.482719333Z 2022-06-20T04:13:36.482Z|00434|reconnect|INFO|ssl:10.0.171.139:9642: connection attempt timed out 2022-06-20T04:13:36.484717455Z 2022-06-20T04:13:36.484Z|00435|reconnect|INFO|ssl:10.0.192.114:9642: connecting... 2022-06-20T04:13:36.510817649Z 2022-06-20T04:13:36.510Z|00436|reconnect|INFO|ssl:10.0.192.114:9642: connected 2022-06-20T04:13:37.079251172Z 2022-06-20T04:13:37.079Z|00437|inc_proc_eng|INFO|node: logical_flow_output, recompute (forced) took 554ms 2022-06-20T04:15:56.289442954Z 2022-06-20T04:15:56.289Z|00438|ovsdb_cs|INFO|ssl:10.0.192.114:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T04:15:56.291290732Z 2022-06-20T04:15:56.291Z|00439|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T04:15:56.291644380Z 2022-06-20T04:15:56.291Z|00440|reconnect|INFO|ssl:10.0.192.114:9642: connection attempt timed out 2022-06-20T04:15:56.293451154Z 2022-06-20T04:15:56.293Z|00441|reconnect|INFO|ssl:10.0.145.30:9642: connecting... 2022-06-20T04:15:57.294413674Z 2022-06-20T04:15:57.294Z|00442|reconnect|INFO|ssl:10.0.145.30:9642: connection attempt timed out 2022-06-20T04:15:57.296414208Z 2022-06-20T04:15:57.296Z|00443|reconnect|INFO|ssl:10.0.171.139:9642: connecting... 2022-06-20T04:15:57.301898418Z 2022-06-20T04:15:57.301Z|00444|reconnect|INFO|ssl:10.0.171.139:9642: connected 2022-06-20T04:15:57.887281200Z 2022-06-20T04:15:57.887Z|00445|inc_proc_eng|INFO|node: logical_flow_output, recompute (forced) took 574ms 2022-06-20T04:16:43.439077037Z 2022-06-20T04:16:43.439Z|00446|ovsdb_cs|INFO|ssl:10.0.171.139:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T04:16:43.440477254Z 2022-06-20T04:16:43.440Z|00447|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T04:16:43.440807816Z 2022-06-20T04:16:43.440Z|00448|reconnect|INFO|ssl:10.0.171.139:9642: connection attempt timed out 2022-06-20T04:16:43.442655410Z 2022-06-20T04:16:43.442Z|00449|reconnect|INFO|ssl:10.0.192.114:9642: connecting... 2022-06-20T04:16:44.443635042Z 2022-06-20T04:16:44.443Z|00450|reconnect|INFO|ssl:10.0.192.114:9642: connection attempt timed out 2022-06-20T04:16:44.445629764Z 2022-06-20T04:16:44.445Z|00451|reconnect|INFO|ssl:10.0.145.30:9642: connecting... 2022-06-20T04:16:44.471305127Z 2022-06-20T04:16:44.471Z|00452|reconnect|INFO|ssl:10.0.145.30:9642: connected 2022-06-20T04:16:45.031873346Z 2022-06-20T04:16:45.031Z|00453|inc_proc_eng|INFO|node: logical_flow_output, recompute (forced) took 547ms 2022-06-20T04:17:28.006790727Z 2022-06-20T04:17:28.006Z|00454|ovsdb_cs|INFO|ssl:10.0.145.30:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T04:17:28.008256490Z 2022-06-20T04:17:28.008Z|00455|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T04:17:28.008593478Z 2022-06-20T04:17:28.008Z|00456|reconnect|INFO|ssl:10.0.145.30:9642: connection attempt timed out 2022-06-20T04:17:28.010466299Z 2022-06-20T04:17:28.010Z|00457|reconnect|INFO|ssl:10.0.171.139:9642: connecting... 2022-06-20T04:17:29.011680387Z 2022-06-20T04:17:29.011Z|00458|reconnect|INFO|ssl:10.0.171.139:9642: connection attempt timed out 2022-06-20T04:17:29.014752700Z 2022-06-20T04:17:29.014Z|00459|reconnect|INFO|ssl:10.0.192.114:9642: connecting... 2022-06-20T04:17:29.022364718Z 2022-06-20T04:17:29.022Z|00460|reconnect|INFO|ssl:10.0.192.114:9642: connected 2022-06-20T04:17:29.585247461Z 2022-06-20T04:17:29.585Z|00461|inc_proc_eng|INFO|node: logical_flow_output, recompute (forced) took 550ms This looks like an OVN bottleneck issue.
Continuation of https://bugzilla.redhat.com/show_bug.cgi?id=2084062#c27, looking at SBDB around this time: SBDB on ovnkube-master-fdmlm: 2022-06-20T03:49:18.564708971Z 2022-06-20T03:49:18.564Z|01115|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:49:28.870556263Z 2022-06-20T03:49:28.870Z|01116|raft|INFO|Dropped 4 log messages in last 19 seconds (most recently, 12 seconds ago) due to excessive rate 2022-06-20T03:49:28.871156160Z 2022-06-20T03:49:28.871Z|01117|raft|INFO|current entry eid 207091e7-846c-4736-8f91-1354689360cb does not match prerequisite df02a2ec-fd85-4103-a4df-57bf6c688fd0 in execute_command_request 2022-06-20T03:49:28.875584571Z 2022-06-20T03:49:28.875Z|01118|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:49:31.364797320Z 2022-06-20T03:49:31.364Z|01119|raft|INFO|Dropped 1 log messages in last 2 seconds (most recently, 2 seconds ago) due to excessive rate 2022-06-20T03:49:31.366424355Z 2022-06-20T03:49:31.366Z|01120|raft|INFO|current entry eid 492be7a7-e29f-44e5-ad0d-22f4b175b895 does not match prerequisite 207091e7-846c-4736-8f91-1354689360cb in execute_command_request 2022-06-20T03:49:31.368117569Z 2022-06-20T03:49:31.368Z|01121|timeval|WARN|Unreasonably long 1465ms poll interval (1411ms user, 39ms system) 2022-06-20T03:49:31.369588451Z 2022-06-20T03:49:31.369Z|01122|timeval|WARN|context switches: 0 voluntary, 13 involuntary 2022-06-20T03:49:31.371032922Z 2022-06-20T03:49:31.371Z|01123|coverage|INFO|Dropped 7 log messages in last 102 seconds (most recently, 51 seconds ago) due to excessive rate 2022-06-20T03:49:31.372486111Z 2022-06-20T03:49:31.372Z|01124|coverage|INFO|Skipping details of duplicate event coverage for hash=884724c9 2022-06-20T03:49:31.373957069Z 2022-06-20T03:49:31.373Z|01125|poll_loop|INFO|Dropped 285 log messages in last 51 seconds (most recently, 49 seconds ago) due to excessive rate 2022-06-20T03:49:31.375399594Z 2022-06-20T03:49:31.375Z|01126|poll_loop|INFO|wakeup due to [POLLOUT] on fd 50 (10.0.145.30:9642<->10.0.156.151:39800) at ../lib/stream-ssl.c:802 (91% CPU usage) 2022-06-20T03:49:31.376832887Z 2022-06-20T03:49:31.376Z|01127|poll_loop|INFO|wakeup due to [POLLOUT] on fd 95 (10.0.145.30:9642<->10.0.219.28:58954) at ../lib/stream-ssl.c:802 (91% CPU usage) 2022-06-20T03:49:31.378263127Z 2022-06-20T03:49:31.378Z|01128|poll_loop|INFO|wakeup due to [POLLOUT] on fd 34 (10.0.145.30:9642<->10.0.171.139:51286) at ../lib/stream-ssl.c:802 (91% CPU usage) 2022-06-20T03:49:31.379694133Z 2022-06-20T03:49:31.379Z|01129|poll_loop|INFO|wakeup due to [POLLOUT] on fd 45 (10.0.145.30:9642<->10.0.157.174:48532) at ../lib/stream-ssl.c:802 (91% CPU usage) 2022-06-20T03:49:31.380862759Z 2022-06-20T03:49:31.380Z|01130|poll_loop|INFO|wakeup due to [POLLOUT] on fd 94 (10.0.145.30:9642<->10.0.197.30:57960) at ../lib/stream-ssl.c:802 (91% CPU usage) 2022-06-20T03:49:31.381773349Z 2022-06-20T03:49:31.381Z|01131|poll_loop|INFO|wakeup due to [POLLIN] on fd 29 (10.0.145.30:9644<->10.0.192.114:40888) at ../lib/stream-ssl.c:836 (91% CPU usage) 2022-06-20T03:49:31.382584249Z 2022-06-20T03:49:31.382Z|01132|poll_loop|INFO|wakeup due to [POLLOUT] on fd 91 (10.0.145.30:9642<->10.0.201.136:48072) at ../lib/stream-ssl.c:802 (91% CPU usage) 2022-06-20T03:49:31.383413708Z 2022-06-20T03:49:31.383Z|01133|poll_loop|INFO|wakeup due to [POLLOUT] on fd 51 (10.0.145.30:9642<->10.0.198.76:33504) at ../lib/stream-ssl.c:802 (91% CPU usage) 2022-06-20T03:49:31.384242345Z 2022-06-20T03:49:31.384Z|01134|poll_loop|INFO|wakeup due to [POLLOUT] on fd 89 (10.0.145.30:9642<->10.0.169.82:51356) at ../lib/stream-ssl.c:802 (91% CPU usage) 2022-06-20T03:49:38.562243124Z 2022-06-20T03:49:38.562Z|01135|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:49:48.554794520Z 2022-06-20T03:49:48.554Z|01136|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:49:50.554809694Z 2022-06-20T03:49:50.554Z|01137|raft|INFO|Dropped 6 log messages in last 19 seconds (most recently, 17 seconds ago) due to excessive rate 2022-06-20T03:49:50.555297892Z 2022-06-20T03:49:50.554Z|01138|raft|INFO|current entry eid d1b2199d-9f5e-44e7-b0e0-94cdbe46f499 does not match prerequisite fd59b73a-06b4-4ff4-85cc-3f31cf4bf78a in execute_command_request 2022-06-20T03:49:58.556889871Z 2022-06-20T03:49:58.556Z|01139|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:49:58.941438245Z 2022-06-20T03:49:58.941Z|01140|raft|INFO|current entry eid 08e3827b-451c-4928-ab31-5153c908a937 does not match prerequisite 8d53af18-b3ed-471d-8890-5e4d17454ae1 in execute_command_request 2022-06-20T03:50:08.559951612Z 2022-06-20T03:50:08.559Z|01141|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:50:13.895505080Z 2022-06-20T03:50:13.895Z|01142|raft|INFO|Dropped 5 log messages in last 12 seconds (most recently, 10 seconds ago) due to excessive rate 2022-06-20T03:50:13.896504384Z 2022-06-20T03:50:13.896Z|01143|raft|INFO|current entry eid 71dd1179-1f42-4e0a-969d-7c5984454772 does not match prerequisite 1c2f3796-9dce-4a59-a89a-95995326a3c8 in execute_command_request 2022-06-20T03:50:13.900576770Z 2022-06-20T03:50:13.900Z|01144|timeval|WARN|Unreasonably long 3035ms poll interval (2895ms user, 101ms system) 2022-06-20T03:50:13.900609615Z 2022-06-20T03:50:13.900Z|01145|timeval|WARN|faults: 38366 minor, 0 major 2022-06-20T03:50:13.900619776Z 2022-06-20T03:50:13.900Z|01146|timeval|WARN|disk: 0 reads, 80720 writes 2022-06-20T03:50:13.900628697Z 2022-06-20T03:50:13.900Z|01147|timeval|WARN|context switches: 0 voluntary, 42 involuntary 2022-06-20T03:50:13.900664086Z 2022-06-20T03:50:13.900Z|01148|coverage|INFO|Skipping details of duplicate event coverage for hash=884724c9 2022-06-20T03:50:13.900714733Z 2022-06-20T03:50:13.900Z|01149|poll_loop|INFO|Dropped 63 log messages in last 43 seconds (most recently, 41 seconds ago) due to excessive rate 2022-06-20T03:50:13.900738874Z 2022-06-20T03:50:13.900Z|01150|poll_loop|INFO|wakeup due to [POLLIN] on fd 89 (10.0.145.30:9642<->10.0.169.82:51356) at ../lib/stream-ssl.c:836 (101% CPU usage) 2022-06-20T03:50:13.900778127Z 2022-06-20T03:50:13.900Z|01151|poll_loop|INFO|wakeup due to [POLLIN] on fd 86 (10.0.145.30:9642<->10.0.183.72:39624) at ../lib/stream-ssl.c:836 (101% CPU usage) 2022-06-20T03:50:13.901113584Z 2022-06-20T03:50:13.901Z|01152|poll_loop|INFO|wakeup due to 0-ms timeout at ../lib/stream-ssl.c:838 (101% CPU usage) 2022-06-20T03:50:13.941973191Z 2022-06-20T03:50:13.941Z|01153|poll_loop|INFO|wakeup due to [POLLOUT] on fd 29 (10.0.145.30:9644<->10.0.192.114:40888) at ../lib/stream-ssl.c:802 (101% CPU usage) 2022-06-20T03:50:13.985964149Z 2022-06-20T03:50:13.985Z|01154|poll_loop|INFO|wakeup due to [POLLOUT] on fd 28 (10.0.145.30:38716<->10.0.171.139:9644) at ../lib/stream-ssl.c:802 (101% CPU usage) 2022-06-20T03:50:14.027555855Z 2022-06-20T03:50:14.027Z|01155|poll_loop|INFO|wakeup due to [POLLOUT] on fd 28 (10.0.145.30:38716<->10.0.171.139:9644) at ../lib/stream-ssl.c:802 (101% CPU usage) 2022-06-20T03:50:14.065940230Z 2022-06-20T03:50:14.065Z|01156|poll_loop|INFO|wakeup due to [POLLOUT] on fd 28 (10.0.145.30:38716<->10.0.171.139:9644) at ../lib/stream-ssl.c:802 (101% CPU usage) 2022-06-20T03:50:17.865091137Z 2022-06-20T03:50:17.865Z|01157|timeval|WARN|Unreasonably long 2590ms poll interval (2460ms user, 89ms system) 2022-06-20T03:50:17.866470604Z 2022-06-20T03:50:17.866Z|01158|timeval|WARN|faults: 35756 minor, 0 major 2022-06-20T03:50:17.867695780Z 2022-06-20T03:50:17.867Z|01159|timeval|WARN|disk: 0 reads, 8 writes 2022-06-20T03:50:17.868975432Z 2022-06-20T03:50:17.868Z|01160|timeval|WARN|context switches: 0 voluntary, 17 involuntary 2022-06-20T03:50:23.593071856Z 2022-06-20T03:50:23.593Z|01161|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T03:50:23.593799375Z 2022-06-20T03:50:23.593Z|01162|jsonrpc|WARN|ssl:10.0.192.114:47844: send error: Broken pipe 2022-06-20T03:50:23.735863518Z 2022-06-20T03:50:23.735Z|01163|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T03:50:23.736605824Z 2022-06-20T03:50:23.736Z|01164|jsonrpc|WARN|ssl:10.0.145.30:38220: send error: Broken pipe 2022-06-20T03:50:23.737730318Z 2022-06-20T03:50:23.737Z|01165|raft|INFO|Dropped 3 log messages in last 9 seconds (most recently, 9 seconds ago) due to excessive rate 2022-06-20T03:50:23.738491008Z 2022-06-20T03:50:23.738Z|01166|raft|INFO|current entry eid d0a837fe-c6ee-4595-8992-9872979ded83 does not match prerequisite 71dd1179-1f42-4e0a-969d-7c5984454772 in execute_command_request 2022-06-20T03:50:23.744365221Z 2022-06-20T03:50:23.744Z|01167|timeval|WARN|Unreasonably long 5874ms poll interval (5239ms user, 520ms system) 2022-06-20T03:50:23.745126664Z 2022-06-20T03:50:23.745Z|01168|timeval|WARN|faults: 49466 minor, 0 major 2022-06-20T03:50:23.745862933Z 2022-06-20T03:50:23.745Z|01169|timeval|WARN|disk: 0 reads, 8 writes 2022-06-20T03:50:23.746587310Z 2022-06-20T03:50:23.746Z|01170|timeval|WARN|context switches: 0 voluntary, 57 involuntary 2022-06-20T03:50:23.747359893Z 2022-06-20T03:50:23.747Z|01171|poll_loop|INFO|Dropped 20 log messages in last 9 seconds (most recently, 5 seconds ago) due to excessive rate 2022-06-20T03:50:23.748100853Z 2022-06-20T03:50:23.748Z|01172|poll_loop|INFO|wakeup due to [POLLOUT] on fd 77 (10.0.145.30:9642<->10.0.158.69:42264) at ../lib/stream-ssl.c:802 (99% CPU usage) 2022-06-20T03:50:23.751819073Z 2022-06-20T03:50:23.751Z|01173|jsonrpc|WARN|unix#1641: send error: Broken pipe 2022-06-20T03:50:23.986131422Z 2022-06-20T03:50:23.986Z|01174|reconnect|WARN|ssl:10.0.192.114:47844: connection dropped (Broken pipe) 2022-06-20T03:50:23.989496103Z 2022-06-20T03:50:23.989Z|01175|reconnect|WARN|ssl:10.0.145.30:38220: connection dropped (Broken pipe) 2022-06-20T03:50:25.286808299Z 2022-06-20T03:50:25.286Z|01176|poll_loop|INFO|Dropped 327 log messages in last 2 seconds (most recently, 0 seconds ago) due to excessive rate 2022-06-20T03:50:25.288619052Z 2022-06-20T03:50:25.288Z|01177|poll_loop|INFO|wakeup due to 0-ms timeout at ../ovsdb/jsonrpc-server.c:605 (99% CPU usage) 2022-06-20T03:50:28.563852214Z 2022-06-20T03:50:28.563Z|01178|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:50:32.589172399Z 2022-06-20T03:50:32.589Z|01179|raft|INFO|Dropped 4074 log messages in last 9 seconds (most recently, 3 seconds ago) due to excessive rate 2022-06-20T03:50:32.589265984Z 2022-06-20T03:50:32.589Z|01180|raft|INFO|current entry eid c2f1e396-37de-4534-a276-876b231e3c58 does not match prerequisite 78d63a8f-eaa4-4225-a7d9-a3c8da3e718b in execute_command_request 2022-06-20T03:50:38.565884119Z 2022-06-20T03:50:38.565Z|01181|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:51:06.230146697Z 2022-06-20T03:51:06.230Z|01182|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T03:51:06.231833716Z 2022-06-20T03:51:06.231Z|01183|jsonrpc|WARN|ssl:10.0.145.30:50088: send error: Broken pipe 2022-06-20T03:51:06.345130960Z 2022-06-20T03:51:06.345Z|01184|raft|INFO|Dropped 1 log messages in last 33 seconds (most recently, 33 seconds ago) due to excessive rate 2022-06-20T03:51:06.346281811Z 2022-06-20T03:51:06.346Z|01185|raft|INFO|current entry eid 0b49ca34-6446-47a4-b221-0953b88ff99f does not match prerequisite 8d59007d-2898-4b0d-ae62-b9e01455ac72 in execute_command_request 2022-06-20T03:51:06.353361066Z 2022-06-20T03:51:06.353Z|01186|raft|INFO|current entry eid 0b49ca34-6446-47a4-b221-0953b88ff99f does not match prerequisite 8d59007d-2898-4b0d-ae62-b9e01455ac72 in execute_command_request 2022-06-20T03:51:06.358954927Z 2022-06-20T03:51:06.358Z|01187|raft|INFO|current entry eid 0b49ca34-6446-47a4-b221-0953b88ff99f does not match prerequisite 8d59007d-2898-4b0d-ae62-b9e01455ac72 in execute_command_request 2022-06-20T03:51:06.418052982Z 2022-06-20T03:51:06.418Z|01188|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T03:51:06.419678075Z 2022-06-20T03:51:06.419Z|01189|jsonrpc|WARN|ssl:10.0.171.139:44150: receive error: Protocol error 2022-06-20T03:51:06.421890736Z 2022-06-20T03:51:06.421Z|01190|timeval|WARN|Unreasonably long 26524ms poll interval (25134ms user, 1032ms system) 2022-06-20T03:51:06.423873459Z 2022-06-20T03:51:06.423Z|01191|timeval|WARN|faults: 473022 minor, 0 major 2022-06-20T03:51:06.425821801Z 2022-06-20T03:51:06.425Z|01192|timeval|WARN|disk: 0 reads, 8 writes 2022-06-20T03:51:06.427651056Z 2022-06-20T03:51:06.427Z|01193|timeval|WARN|context switches: 0 voluntary, 287 involuntary 2022-06-20T03:51:06.429467805Z 2022-06-20T03:51:06.429Z|01194|coverage|INFO|Dropped 2 log messages in last 48 seconds (most recently, 43 seconds ago) due to excessive rate 2022-06-20T03:51:06.431092355Z 2022-06-20T03:51:06.431Z|01195|coverage|INFO|Skipping details of duplicate event coverage for hash=884724c9 2022-06-20T03:51:06.433043105Z 2022-06-20T03:51:06.433Z|01196|poll_loop|INFO|Dropped 645 log messages in last 41 seconds (most recently, 37 seconds ago) due to excessive rate 2022-06-20T03:51:06.434913301Z 2022-06-20T03:51:06.434Z|01197|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (94% CPU usage) 2022-06-20T03:51:06.436794684Z 2022-06-20T03:51:06.436Z|01198|poll_loop|INFO|wakeup due to [POLLOUT] on fd 34 (10.0.145.30:9642<->10.0.171.139:51286) at ../lib/stream-ssl.c:802 (94% CPU usage) 2022-06-20T03:51:06.438215466Z 2022-06-20T03:51:06.438Z|01199|poll_loop|INFO|wakeup due to [POLLIN] on fd 45 (10.0.145.30:9642<->10.0.157.174:48532) at ../lib/stream-ssl.c:836 (94% CPU usage) 2022-06-20T03:51:06.439710520Z 2022-06-20T03:51:06.439Z|01200|poll_loop|INFO|wakeup due to [POLLIN] on fd 52 (10.0.145.30:9642<->10.0.134.14:50860) at ../lib/stream-ssl.c:836 (94% CPU usage) 2022-06-20T03:51:06.441120359Z 2022-06-20T03:51:06.441Z|01201|poll_loop|INFO|wakeup due to [POLLIN] on fd 72 (10.0.145.30:9642<->10.0.135.14:45422) at ../lib/stream-ssl.c:836 (94% CPU usage) 2022-06-20T03:51:06.442506942Z 2022-06-20T03:51:06.442Z|01202|poll_loop|INFO|wakeup due to [POLLIN] on fd 82 (10.0.145.30:9642<->10.0.190.145:35550) at ../lib/stream-ssl.c:836 (94% CPU usage) 2022-06-20T03:51:06.443949268Z 2022-06-20T03:51:06.443Z|01203|memory|INFO|peak resident set size grew 68% in last 419.2 seconds, from 3683456 kB to 6206252 kB 2022-06-20T03:51:06.445320501Z 2022-06-20T03:51:06.445Z|01204|memory|INFO|atoms:16013362 backlog:5446252 cells:12150859 monitors:5 raft-connections:5 raft-log:1161 sessions:54 txn-history:100 txn-history-atoms:5013 2022-06-20T03:51:06.457297841Z 2022-06-20T03:51:06.457Z|01205|jsonrpc|WARN|unix#1648: send error: Broken pipe 2022-06-20T03:51:06.461131776Z 2022-06-20T03:51:06.461Z|01206|jsonrpc|WARN|unix#1649: send error: Broken pipe 2022-06-20T03:51:06.464396705Z 2022-06-20T03:51:06.464Z|01207|jsonrpc|WARN|unix#1650: send error: Broken pipe 2022-06-20T03:51:06.467402342Z 2022-06-20T03:51:06.467Z|01208|jsonrpc|WARN|unix#1651: send error: Broken pipe 2022-06-20T03:51:06.476328046Z 2022-06-20T03:51:06.476Z|01209|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T03:51:06.477502689Z 2022-06-20T03:51:06.477Z|01210|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T03:51:06.479557549Z 2022-06-20T03:51:06.479Z|01211|reconnect|WARN|ssl:10.0.171.139:51286: connection dropped (Broken pipe) 2022-06-20T03:51:06.482463007Z 2022-06-20T03:51:06.482Z|01212|reconnect|WARN|ssl:10.0.145.30:50088: connection dropped (Broken pipe) 2022-06-20T03:51:06.484566869Z 2022-06-20T03:51:06.484Z|01213|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T03:51:06.486443738Z 2022-06-20T03:51:06.486Z|01214|reconnect|WARN|ssl:10.0.192.114:52076: connection dropped (Broken pipe) 2022-06-20T03:51:06.520911440Z 2022-06-20T03:51:06.520Z|01215|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T03:51:06.522311572Z 2022-06-20T03:51:06.522Z|01216|raft|INFO|server 5869 is leader for term 10 2022-06-20T03:51:06.523822870Z 2022-06-20T03:51:06.523Z|01217|raft|INFO|rejecting append_request because previous entry 10,9457 not in local log (mismatch past end of log) 2022-06-20T03:51:06.524948572Z 2022-06-20T03:51:06.524Z|01218|raft|INFO|rejecting append_request because previous entry 10,9458 not in local log (mismatch past end of log) 2022-06-20T03:51:06.526292549Z 2022-06-20T03:51:06.526Z|01219|raft|INFO|rejected append_reply (not leader) 2022-06-20T03:51:06.527689491Z 2022-06-20T03:51:06.527Z|01220|raft|WARN|ignoring vote request received after only 2 ms (minimum election time is 16000 ms) 2022-06-20T03:51:06.529215359Z 2022-06-20T03:51:06.529Z|01221|raft|INFO|8271 truncating 1 entries from end of log 2022-06-20T03:51:06.530803561Z 2022-06-20T03:51:06.530Z|01222|reconnect|WARN|ssl:10.0.171.139:44150: connection dropped (Protocol error) 2022-06-20T03:51:06.546731842Z 2022-06-20T03:51:06.546Z|01223|reconnect|WARN|ssl:10.0.145.30:52006: connection dropped (Protocol error) 2022-06-20T03:51:06.548268230Z 2022-06-20T03:51:06.548Z|01224|reconnect|INFO|ssl:10.0.192.114:9644: connection closed by peer 2022-06-20T03:51:07.531690244Z 2022-06-20T03:51:07.531Z|01225|poll_loop|INFO|Dropped 8 log messages in last 1 seconds (most recently, 1 seconds ago) due to excessive rate 2022-06-20T03:51:07.533116387Z 2022-06-20T03:51:07.533Z|01226|poll_loop|INFO|wakeup due to [POLLIN] on fd 85 (10.0.145.30:9642<->10.0.177.152:39048) at ../lib/stream-ssl.c:836 (94% CPU usage) 2022-06-20T03:51:07.553524833Z 2022-06-20T03:51:07.553Z|01227|reconnect|INFO|ssl:10.0.192.114:9644: connecting... 2022-06-20T03:51:07.576598760Z 2022-06-20T03:51:07.576Z|01228|reconnect|INFO|ssl:10.0.192.114:9644: connected 2022-06-20T03:51:08.571403531Z 2022-06-20T03:51:08.571Z|01229|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:51:16.827774157Z 2022-06-20T03:51:16.827Z|01230|raft|WARN|ignoring vote request received after only 10297 ms (minimum election time is 16000 ms) 2022-06-20T03:51:18.567945732Z 2022-06-20T03:51:18.567Z|01231|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:51:28.568416137Z 2022-06-20T03:51:28.568Z|01232|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:51:28.746445552Z 2022-06-20T03:51:28.746Z|01233|raft|INFO|rejecting append_request because previous entry 10,9458 not in local log (mismatch past end of log) 2022-06-20T03:51:28.820787688Z 2022-06-20T03:51:28.820Z|01234|raft|INFO|rejecting append_request because previous entry 10,9458 not in local log (mismatch past end of log) 2022-06-20T03:51:28.825659826Z 2022-06-20T03:51:28.825Z|01235|raft|INFO|ssl:10.0.171.139:44850: learned server ID 5869 2022-06-20T03:51:28.825689732Z 2022-06-20T03:51:28.825Z|01236|raft|INFO|ssl:10.0.171.139:44850: learned remote address ssl:10.0.171.139:9644 2022-06-20T03:51:28.825731755Z 2022-06-20T03:51:28.825Z|01237|raft|INFO|rejected append_reply (not leader) 2022-06-20T03:51:33.204936118Z 2022-06-20T03:51:33.204Z|01238|raft|WARN|ignoring vote request received after only 4379 ms (minimum election time is 16000 ms) 2022-06-20T03:51:38.560775431Z 2022-06-20T03:51:38.560Z|01239|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:51:45.186595527Z 2022-06-20T03:51:45.186Z|01240|raft|INFO|server 5869 is leader for term 12 2022-06-20T03:51:47.928147166Z 2022-06-20T03:51:47.928Z|01241|raft|INFO|server 1f8e is leader for term 13 2022-06-20T03:51:48.554949527Z 2022-06-20T03:51:48.554Z|01242|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:51:58.668324699Z 2022-06-20T03:51:58.668Z|01243|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:52:07.692923619Z 2022-06-20T03:52:07.692Z|01244|raft|INFO|term 14: 16700 ms timeout expired, starting election 2022-06-20T03:52:14.507263051Z 2022-06-20T03:52:14.507Z|01245|raft|INFO|rejecting term 13 < current term 14 received in vote_reply message from server 5869 2022-06-20T03:52:15.587639130Z 2022-06-20T03:52:15.587Z|01246|reconnect|ERR|ssl:10.0.192.114:9644: no response to inactivity probe after 17 seconds, disconnecting 2022-06-20T03:52:15.587683688Z 2022-06-20T03:52:15.587Z|01247|reconnect|INFO|ssl:10.0.192.114:9644: connection dropped 2022-06-20T03:52:16.589039472Z 2022-06-20T03:52:16.588Z|01248|reconnect|INFO|ssl:10.0.192.114:9644: connecting... 2022-06-20T03:52:17.590265863Z 2022-06-20T03:52:17.590Z|01249|reconnect|INFO|ssl:10.0.192.114:9644: connection attempt timed out 2022-06-20T03:52:17.590360460Z 2022-06-20T03:52:17.590Z|01250|reconnect|INFO|ssl:10.0.192.114:9644: waiting 2 seconds before reconnect 2022-06-20T03:52:19.592224107Z 2022-06-20T03:52:19.592Z|01251|reconnect|INFO|ssl:10.0.192.114:9644: connecting... 2022-06-20T03:52:19.661111428Z 2022-06-20T03:52:19.661Z|01252|raft|INFO|rejecting term 13 < current term 14 received in append_request message from server 1f8e 2022-06-20T03:52:19.708743405Z 2022-06-20T03:52:19.708Z|01253|raft|INFO|rejecting term 13 < current term 14 received in vote_reply message from server 1f8e 2022-06-20T03:52:19.840637467Z 2022-06-20T03:52:19.840Z|01254|reconnect|INFO|ssl:10.0.192.114:9644: connected 2022-06-20T03:52:23.596419465Z 2022-06-20T03:52:23.596Z|01255|poll_loop|INFO|Dropped 9 log messages in last 76 seconds (most recently, 74 seconds ago) due to excessive rate 2022-06-20T03:52:23.596571799Z 2022-06-20T03:52:23.596Z|01256|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (71% CPU usage) 2022-06-20T03:52:23.600934528Z 2022-06-20T03:52:23.600Z|01257|poll_loop|INFO|wakeup due to [POLLIN] on fd 70 (10.0.145.30:9642<->10.0.171.139:32824) at ../lib/stream-ssl.c:825 (71% CPU usage) 2022-06-20T03:52:23.602958972Z 2022-06-20T03:52:23.602Z|01258|poll_loop|INFO|wakeup due to 0-ms timeout at ssl:10.0.171.139:32824 (71% CPU usage) 2022-06-20T03:52:23.605907945Z 2022-06-20T03:52:23.605Z|01259|poll_loop|INFO|wakeup due to 0-ms timeout at ssl:10.0.171.139:32824 (71% CPU usage) 2022-06-20T03:52:23.607487346Z 2022-06-20T03:52:23.607Z|01260|poll_loop|INFO|wakeup due to [POLLIN] on fd 70 (10.0.145.30:9642<->10.0.171.139:32824) at ../lib/stream-ssl.c:836 (71% CPU usage) 2022-06-20T03:52:23.607589467Z 2022-06-20T03:52:23.607Z|01261|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (71% CPU usage) 2022-06-20T03:52:23.610891261Z 2022-06-20T03:52:23.610Z|01262|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (71% CPU usage) 2022-06-20T03:52:23.614979031Z 2022-06-20T03:52:23.614Z|01263|poll_loop|INFO|wakeup due to 0-ms timeout at ssl:10.0.171.139:32824 (71% CPU usage) 2022-06-20T03:52:23.617406082Z 2022-06-20T03:52:23.617Z|01264|poll_loop|INFO|wakeup due to 0-ms timeout at ssl:10.0.171.139:32824 (71% CPU usage) 2022-06-20T03:52:23.621084164Z 2022-06-20T03:52:23.621Z|01265|poll_loop|INFO|wakeup due to 0-ms timeout at ssl:10.0.192.114:57616 (71% CPU usage) 2022-06-20T03:52:23.916552587Z 2022-06-20T03:52:23.916Z|01266|raft|INFO|term 15: 16223 ms timeout expired, starting election 2022-06-20T03:52:23.927626055Z 2022-06-20T03:52:23.927Z|01267|raft|INFO|rejecting term 13 < current term 15 received in vote_reply message from server 5869 2022-06-20T03:52:35.726173444Z 2022-06-20T03:52:35.726Z|01268|raft|INFO|rejecting term 14 < current term 15 received in vote_request message from server 5869 2022-06-20T03:52:35.729412322Z 2022-06-20T03:52:35.729Z|01269|raft|INFO|rejecting term 14 < current term 15 received in append_request message from server 5869 2022-06-20T03:52:40.389078554Z 2022-06-20T03:52:40.389Z|01270|raft|INFO|term 16: 16472 ms timeout expired, starting election 2022-06-20T03:52:40.393064111Z 2022-06-20T03:52:40.393Z|01271|raft|INFO|rejecting term 14 < current term 16 received in vote_reply message from server 1f8e 2022-06-20T03:52:51.665392921Z 2022-06-20T03:52:51.665Z|01272|raft|INFO|8271 received "lost leadership" reply from 1f8e for unknown command 2022-06-20T03:52:51.974161505Z 2022-06-20T03:52:51.974Z|01273|raft|INFO|server 5869 is leader for term 16 2022-06-20T03:52:51.974839125Z 2022-06-20T03:52:51.974Z|01274|raft|INFO|rejecting append_request because previous entry 14,9504 not in local log (mismatch past end of log) 2022-06-20T03:52:58.574849232Z 2022-06-20T03:52:58.574Z|01275|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:53:08.564635041Z 2022-06-20T03:53:08.563Z|01276|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:53:11.163043599Z 2022-06-20T03:53:11.163Z|01277|raft|INFO|term 17: 16524 ms timeout expired, starting election 2022-06-20T03:53:11.168571011Z 2022-06-20T03:53:11.168Z|01278|raft|INFO|term 17: elected leader by 2+ of 3 servers 2022-06-20T03:53:18.567049421Z 2022-06-20T03:53:18.567Z|01279|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:53:22.505712307Z 2022-06-20T03:53:22.505Z|01280|reconnect|ERR|ssl:10.0.171.139:9644: no response to inactivity probe after 17 seconds, disconnecting 2022-06-20T03:53:22.505747924Z 2022-06-20T03:53:22.505Z|01281|reconnect|INFO|ssl:10.0.171.139:9644: connection dropped 2022-06-20T03:53:23.506532333Z 2022-06-20T03:53:23.506Z|01282|reconnect|INFO|ssl:10.0.171.139:9644: connecting... 2022-06-20T03:53:24.000489486Z 2022-06-20T03:53:24.000Z|01283|raft|INFO|rejecting term 16 < current term 17 received in append_request message from server 5869 2022-06-20T03:53:24.059106735Z 2022-06-20T03:53:24.059Z|01284|reconnect|INFO|ssl:10.0.171.139:9644: connected 2022-06-20T03:53:24.163209124Z 2022-06-20T03:53:24.163Z|01285|raft|INFO|Dropped 2 log messages in last 138 seconds (most recently, 138 seconds ago) due to excessive rate 2022-06-20T03:53:24.163247049Z 2022-06-20T03:53:24.163Z|01286|raft|INFO|current entry eid 52b44fb3-e5bf-489c-8b36-b2b36e64faae does not match prerequisite e02dd7d2-1b67-4f9b-a75d-106e234b9c0c in execute_command_request 2022-06-20T03:53:24.163553439Z 2022-06-20T03:53:24.163Z|01287|raft|INFO|current entry eid 52b44fb3-e5bf-489c-8b36-b2b36e64faae does not match prerequisite e02dd7d2-1b67-4f9b-a75d-106e234b9c0c in execute_command_request 2022-06-20T03:53:24.163854266Z 2022-06-20T03:53:24.163Z|01288|raft|INFO|current entry eid 52b44fb3-e5bf-489c-8b36-b2b36e64faae does not match prerequisite e02dd7d2-1b67-4f9b-a75d-106e234b9c0c in execute_command_request 2022-06-20T03:53:24.164137443Z 2022-06-20T03:53:24.164Z|01289|raft|INFO|current entry eid 52b44fb3-e5bf-489c-8b36-b2b36e64faae does not match prerequisite e02dd7d2-1b67-4f9b-a75d-106e234b9c0c in execute_command_request 2022-06-20T03:53:24.164418552Z 2022-06-20T03:53:24.164Z|01290|raft|INFO|current entry eid 52b44fb3-e5bf-489c-8b36-b2b36e64faae does not match prerequisite e02dd7d2-1b67-4f9b-a75d-106e234b9c0c in execute_command_request 2022-06-20T03:53:28.572655918Z 2022-06-20T03:53:28.572Z|01291|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:53:38.563015675Z 2022-06-20T03:53:38.562Z|01292|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:54:05.998454895Z 2022-06-20T03:54:05.998Z|01293|raft|INFO|Dropped 375 log messages in last 42 seconds (most recently, 33 seconds ago) due to excessive rate 2022-06-20T03:54:06.000010162Z 2022-06-20T03:54:05.999Z|01294|raft|INFO|current entry eid fe965224-88f7-4eaf-aedc-e6c42f2012cd does not match prerequisite ebab11dc-d83a-4051-9bde-01391adde1cb in execute_command_request 2022-06-20T03:54:06.004160126Z 2022-06-20T03:54:06.004Z|01295|raft|INFO|current entry eid fe965224-88f7-4eaf-aedc-e6c42f2012cd does not match prerequisite ebab11dc-d83a-4051-9bde-01391adde1cb in execute_command_request 2022-06-20T03:54:06.009791221Z 2022-06-20T03:54:06.009Z|01296|raft|INFO|current entry eid fe965224-88f7-4eaf-aedc-e6c42f2012cd does not match prerequisite ebab11dc-d83a-4051-9bde-01391adde1cb in execute_command_request 2022-06-20T03:54:06.070672686Z 2022-06-20T03:54:06.070Z|01297|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T03:54:06.072141890Z 2022-06-20T03:54:06.072Z|01298|jsonrpc|WARN|Dropped 6 log messages in last 180 seconds (most recently, 180 seconds ago) due to excessive rate 2022-06-20T03:54:06.073526357Z 2022-06-20T03:54:06.073Z|01299|jsonrpc|WARN|ssl:10.0.171.139:55560: receive error: Protocol error 2022-06-20T03:54:06.075145898Z 2022-06-20T03:54:06.075Z|01300|timeval|WARN|Unreasonably long 25500ms poll interval (24927ms user, 215ms system) 2022-06-20T03:54:06.076512710Z 2022-06-20T03:54:06.076Z|01301|timeval|WARN|faults: 2929 minor, 0 major 2022-06-20T03:54:06.077886278Z 2022-06-20T03:54:06.077Z|01302|timeval|WARN|disk: 0 reads, 8 writes 2022-06-20T03:54:06.079320710Z 2022-06-20T03:54:06.079Z|01303|timeval|WARN|context switches: 0 voluntary, 462 involuntary 2022-06-20T03:54:06.083315312Z 2022-06-20T03:54:06.083Z|01304|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour, hash=7c65db81: 2022-06-20T03:54:06.084675556Z 2022-06-20T03:54:06.084Z|01305|coverage|INFO|raft_entry_serialize 0.0/sec 0.767/sec 2.3181/sec total: 9575 2022-06-20T03:54:06.085880022Z 2022-06-20T03:54:06.085Z|01306|coverage|INFO|hmap_pathological 0.0/sec 6.883/sec 204.8350/sec total: 738363 2022-06-20T03:54:06.087110389Z 2022-06-20T03:54:06.087Z|01307|coverage|INFO|hmap_expand 2.0/sec 144.233/sec 4402.6808/sec total: 17513174 2022-06-20T03:54:06.088284355Z 2022-06-20T03:54:06.088Z|01308|coverage|INFO|lockfile_lock 0.0/sec 0.000/sec 0.0000/sec total: 1 2022-06-20T03:54:06.089473696Z 2022-06-20T03:54:06.089Z|01309|coverage|INFO|poll_create_node 6.4/sec 90.800/sec 11278.6339/sec total: 41019875 2022-06-20T03:54:06.090748258Z 2022-06-20T03:54:06.090Z|01310|coverage|INFO|poll_zero_timeout 0.6/sec 1.350/sec 9.5375/sec total: 45074 2022-06-20T03:54:06.091963832Z 2022-06-20T03:54:06.091Z|01311|coverage|INFO|seq_change 0.8/sec 9.650/sec 199.1497/sec total: 747219 2022-06-20T03:54:06.093023705Z 2022-06-20T03:54:06.093Z|01312|coverage|INFO|pstream_open 0.0/sec 0.000/sec 0.0000/sec total: 4 2022-06-20T03:54:06.093974358Z 2022-06-20T03:54:06.093Z|01313|coverage|INFO|stream_open 0.0/sec 0.017/sec 0.0011/sec total: 6 2022-06-20T03:54:06.094964533Z 2022-06-20T03:54:06.094Z|01314|coverage|INFO|unixctl_received 0.4/sec 0.167/sec 0.3308/sec total: 1695 2022-06-20T03:54:06.095914697Z 2022-06-20T03:54:06.095Z|01315|coverage|INFO|unixctl_replied 0.4/sec 0.167/sec 0.3308/sec total: 1695 2022-06-20T03:54:06.096904129Z 2022-06-20T03:54:06.096Z|01316|coverage|INFO|util_xalloc 53.2/sec 4346.917/sec 262986.5161/sec total: 1023782124 2022-06-20T03:54:06.097864152Z 2022-06-20T03:54:06.097Z|01317|coverage|INFO|99 events never hit 2022-06-20T03:54:06.098853273Z 2022-06-20T03:54:06.098Z|01318|poll_loop|INFO|Dropped 1683 log messages in last 103 seconds (most recently, 100 seconds ago) due to excessive rate 2022-06-20T03:54:06.099879466Z 2022-06-20T03:54:06.099Z|01319|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (91% CPU usage) 2022-06-20T03:54:06.100872682Z 2022-06-20T03:54:06.100Z|01320|poll_loop|INFO|wakeup due to [POLLOUT][POLLERR][POLLHUP] on fd 35 (10.0.145.30:9642<->) at ../lib/stream-ssl.c:802 (91% CPU usage) 2022-06-20T03:54:06.101852925Z 2022-06-20T03:54:06.101Z|01321|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (91% CPU usage) 2022-06-20T03:54:06.110560051Z 2022-06-20T03:54:06.110Z|01322|jsonrpc|WARN|unix#1701: send error: Broken pipe 2022-06-20T03:54:06.115180897Z 2022-06-20T03:54:06.115Z|01323|jsonrpc|WARN|unix#1702: send error: Broken pipe 2022-06-20T03:54:06.119401171Z 2022-06-20T03:54:06.119Z|01324|jsonrpc|WARN|unix#1703: send error: Broken pipe 2022-06-20T03:54:06.123561598Z 2022-06-20T03:54:06.123Z|01325|jsonrpc|WARN|unix#1704: send error: Broken pipe 2022-06-20T03:54:06.136233729Z 2022-06-20T03:54:06.136Z|01326|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T03:54:06.138845843Z 2022-06-20T03:54:06.138Z|01327|stream_ssl|WARN|SSL_write: error:1409E10F:SSL routines:ssl3_write_bytes:bad length 2022-06-20T03:54:06.166478611Z 2022-06-20T03:54:06.166Z|01328|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T03:54:06.167936905Z 2022-06-20T03:54:06.167Z|01329|raft|INFO|rejected append_reply (not leader) 2022-06-20T03:54:06.169772435Z 2022-06-20T03:54:06.169Z|01330|raft|WARN|ignoring vote request received after only 1 ms (minimum election time is 16000 ms) 2022-06-20T03:54:06.171210375Z 2022-06-20T03:54:06.171Z|01331|raft|INFO|server 5869 is leader for term 18 2022-06-20T03:54:06.172457778Z 2022-06-20T03:54:06.172Z|01332|raft|INFO|8271 truncating 1 entries from end of log 2022-06-20T03:54:06.173801175Z 2022-06-20T03:54:06.173Z|01333|reconnect|WARN|ssl:10.0.171.139:55560: connection dropped (Protocol error) 2022-06-20T03:54:06.175117186Z 2022-06-20T03:54:06.175Z|01334|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (91% CPU usage) 2022-06-20T03:54:06.182183794Z 2022-06-20T03:54:06.182Z|01335|reconnect|WARN|ssl:10.0.192.114:35138: connection dropped (Input/output error) 2022-06-20T03:54:06.183877044Z 2022-06-20T03:54:06.183Z|01336|reconnect|WARN|ssl:10.0.145.30:41846: connection dropped (Protocol error) 2022-06-20T03:54:06.201638143Z 2022-06-20T03:54:06.201Z|01337|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T03:54:06.201788686Z 2022-06-20T03:54:06.201Z|01338|reconnect|INFO|ssl:10.0.192.114:9644: connection closed by peer 2022-06-20T03:54:06.201876656Z 2022-06-20T03:54:06.201Z|01339|poll_loop|INFO|wakeup due to [POLLIN] on fd 33 (10.0.145.30:9642<->10.0.145.30:40024) at ../lib/stream-ssl.c:836 (91% CPU usage) 2022-06-20T03:54:06.201903289Z 2022-06-20T03:54:06.201Z|01340|poll_loop|INFO|wakeup due to [POLLIN] on fd 28 (10.0.145.30:9642<->10.0.192.114:34982) at ../lib/stream-ssl.c:836 (91% CPU usage) 2022-06-20T03:54:06.201923855Z 2022-06-20T03:54:06.201Z|01341|poll_loop|INFO|wakeup due to [POLLIN] on fd 31 (10.0.145.30:9642<->10.0.171.139:38520) at ../lib/stream-ssl.c:836 (91% CPU usage) 2022-06-20T03:54:06.202194098Z 2022-06-20T03:54:06.202Z|01342|reconnect|WARN|ssl:10.0.171.139:39120: connection dropped (Protocol error) 2022-06-20T03:54:06.202302122Z 2022-06-20T03:54:06.202Z|01343|poll_loop|INFO|wakeup due to 0-ms timeout at ssl:10.0.192.114:34982 (91% CPU usage) 2022-06-20T03:54:07.201834890Z 2022-06-20T03:54:07.201Z|01344|poll_loop|INFO|wakeup due to 1000-ms timeout at ../lib/reconnect.c:677 (91% CPU usage) 2022-06-20T03:54:07.202481631Z 2022-06-20T03:54:07.202Z|01345|reconnect|INFO|ssl:10.0.192.114:9644: connecting... 2022-06-20T03:54:07.204688381Z 2022-06-20T03:54:07.204Z|01346|poll_loop|INFO|wakeup due to [POLLOUT] on fd 28 (10.0.145.30:53202<->10.0.192.114:9644) at ../lib/stream-ssl.c:818 (91% CPU usage) 2022-06-20T03:54:07.208233266Z 2022-06-20T03:54:07.208Z|01347|reconnect|INFO|ssl:10.0.192.114:9644: connected 2022-06-20T03:54:08.569534660Z 2022-06-20T03:54:08.569Z|01348|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:54:12.766685946Z 2022-06-20T03:54:12.766Z|01349|raft|WARN|ignoring vote request received after only 6593 ms (minimum election time is 16000 ms) 2022-06-20T03:54:18.562948028Z 2022-06-20T03:54:18.562Z|01350|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T03:54:24.998984730Z 2022-06-20T03:54:24.998Z|01351|raft|INFO|ssl:10.0.171.139:56180: learned server ID 5869 2022-06-20T03:54:24.999024638Z 2022-06-20T03:54:24.999Z|01352|raft|INFO|ssl:10.0.171.139:56180: learned remote address ssl:10.0.171.139:9644 2022-06-20T03:54:25.001932815Z 2022-06-20T03:54:25.001Z|01353|raft|INFO|rejected append_reply (not leader) 2022-06-20T03:54:28.835628327Z 2022-06-20T03:54:28.835Z|01354|raft|WARN|ignoring vote request received after only 3984 ms (minimum election time is 16000 ms) 2022-06-20T03:54:40.967263390Z 2022-06-20T03:54:40.967Z|01355|raft|INFO|term 20: 16116 ms timeout expired, starting election 2022-06-20T03:54:40.972173088Z 2022-06-20T03:54:40.972Z|01356|raft|INFO|rejecting term 19 < current term 20 received in vote_reply message from server 5869 2022-06-20T03:55:11.713499074Z 2022-06-20T03:55:11.713Z|01357|ovsdb|INFO|OVN_Southbound: Database compaction took 24746ms 2022-06-20T03:55:11.771613762Z 2022-06-20T03:55:11.771Z|01358|timeval|WARN|Unreasonably long 24806ms poll interval (21554ms user, 479ms system) 2022-06-20T03:55:11.773046606Z 2022-06-20T03:55:11.773Z|01359|timeval|WARN|faults: 504 minor, 0 major 2022-06-20T03:55:11.774473427Z 2022-06-20T03:55:11.774Z|01360|timeval|WARN|disk: 0 reads, 907960 writes 2022-06-20T03:55:11.775849992Z 2022-06-20T03:55:11.775Z|01361|timeval|WARN|context switches: 4286 voluntary, 322 involuntary 2022-06-20T03:55:11.777212545Z 2022-06-20T03:55:11.777Z|01362|coverage|INFO|Skipping details of duplicate event coverage for hash=7c65db81 2022-06-20T03:55:11.778556389Z 2022-06-20T03:55:11.778Z|01363|poll_loop|INFO|Dropped 7 log messages in last 65 seconds (most recently, 64 seconds ago) due to excessive rate 2022-06-20T03:55:11.779949479Z 2022-06-20T03:55:11.779Z|01364|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (85% CPU usage) 2022-06-20T03:55:11.782590765Z 2022-06-20T03:55:11.782Z|01365|poll_loop|INFO|wakeup due to [POLLIN] on fd 33 (10.0.145.30:9642<->10.0.177.126:48254) at ../lib/stream-ssl.c:836 (85% CPU usage) 2022-06-20T03:55:11.785265591Z 2022-06-20T03:55:11.785Z|01366|poll_loop|INFO|wakeup due to [POLLIN] on fd 29 (10.0.145.30:9644<->10.0.192.114:40888) at ../lib/stream-ssl.c:836 (85% CPU usage) 2022-06-20T03:55:11.787894879Z 2022-06-20T03:55:11.787Z|01367|poll_loop|INFO|wakeup due to [POLLIN] on fd 28 (10.0.145.30:53202<->10.0.192.114:9644) at ../lib/stream-ssl.c:836 (85% CPU usage) 2022-06-20T03:55:11.790498679Z 2022-06-20T03:55:11.790Z|01368|poll_loop|INFO|wakeup due to [POLLIN] on fd 22 (10.0.145.30:33338<->10.0.171.139:9644) at ../lib/stream-ssl.c:836 (85% CPU usage) 2022-06-20T03:55:11.793129516Z 2022-06-20T03:55:11.793Z|01369|poll_loop|INFO|wakeup due to [POLLIN] on fd 35 (10.0.145.30:9642<->10.0.197.30:38812) at ../lib/stream-ssl.c:836 (85% CPU usage) 2022-06-20T03:55:11.795735199Z 2022-06-20T03:55:11.795Z|01370|poll_loop|INFO|wakeup due to [POLLIN] on fd 43 (10.0.145.30:9642<->10.0.156.132:44948) at ../lib/stream-ssl.c:836 (85% CPU usage) 2022-06-20T03:55:11.798346217Z 2022-06-20T03:55:11.798Z|01371|poll_loop|INFO|wakeup due to [POLLIN] on fd 30 (10.0.145.30:9644<->10.0.171.139:56180) at ../lib/stream-ssl.c:836 (85% CPU usage) 2022-06-20T03:55:11.799687945Z 2022-06-20T03:55:11.799Z|01372|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (85% CPU usage) 2022-06-20T03:55:11.808921471Z 2022-06-20T03:55:11.808Z|01373|jsonrpc|WARN|Dropped 6 log messages in last 66 seconds (most recently, 66 seconds ago) due to excessive rate 2022-06-20T03:55:11.810234540Z 2022-06-20T03:55:11.810Z|01374|jsonrpc|WARN|unix#1720: send error: Broken pipe 2022-06-20T03:55:11.811602163Z 2022-06-20T03:55:11.811Z|01375|jsonrpc|WARN|unix#1721: send error: Broken pipe 2022-06-20T03:55:11.812970486Z 2022-06-20T03:55:11.812Z|01376|jsonrpc|WARN|unix#1722: send error: Broken pipe 2022-06-20T03:55:11.814303825Z 2022-06-20T03:55:11.814Z|01377|jsonrpc|WARN|unix#1724: send error: Broken pipe 2022-06-20T03:55:11.815668019Z 2022-06-20T03:55:11.815Z|01378|jsonrpc|WARN|unix#1725: send error: Broken pipe 2022-06-20T03:55:11.821069316Z 2022-06-20T03:55:11.821Z|01379|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T03:55:11.855366243Z 2022-06-20T03:55:11.855Z|01380|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T03:55:11.856815746Z 2022-06-20T03:55:11.856Z|01381|raft|INFO|rejecting term 20 < current term 21 received in vote_request message from server 5869 2022-06-20T03:55:11.858165653Z 2022-06-20T03:55:11.858Z|01382|raft|INFO|term 22: 26221 ms timeout expired, starting election 2022-06-20T03:55:11.859549518Z 2022-06-20T03:55:11.859Z|01383|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (85% CPU usage) 2022-06-20T03:55:11.880314977Z 2022-06-20T03:55:11.880Z|01384|reconnect|WARN|ssl:10.0.192.114:40246: connection dropped (Broken pipe) 2022-06-20T03:55:11.881625890Z 2022-06-20T03:55:11.881Z|01385|reconnect|WARN|ssl:10.0.171.139:43918: connection dropped (Protocol error) 2022-06-20T03:55:11.915624613Z 2022-06-20T03:55:11.915Z|01386|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T03:55:11.921849014Z 2022-06-20T03:55:11.921Z|01387|reconnect|WARN|ssl:10.0.145.30:47124: connection dropped (Protocol error) 2022-06-20T03:55:11.957415776Z 2022-06-20T03:55:11.957Z|01388|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T03:55:11.958877532Z 2022-06-20T03:55:11.958Z|01389|raft|INFO|term 22: elected leader by 2+ of 3 servers 2022-06-20T03:55:11.964764876Z 2022-06-20T03:55:11.964Z|01390|reconnect|WARN|ssl:10.0.192.114:40328: connection dropped (Protocol error) 2022-06-20T03:55:11.998547771Z 2022-06-20T03:55:11.998Z|01391|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T03:55:12.043833037Z 2022-06-20T03:55:12.043Z|01392|reconnect|WARN|ssl:10.0.145.30:47274: connection dropped (Protocol error) 2022-06-20T03:55:12.044874323Z 2022-06-20T03:55:12.044Z|01393|stream_ssl|WARN|SSL_accept: system error (Success) same-ish errors on other 2 SBDB's as well: 2022-06-20T04:01:02.859133433Z 2022-06-20T04:01:02.859Z|01606|timeval|WARN|Unreasonably long 23998ms poll interval (23567ms user, 184ms system) 2022-06-20T04:01:02.860524046Z 2022-06-20T04:01:02.860Z|01607|timeval|WARN|faults: 2579 minor, 0 major 2022-06-20T04:01:02.861897844Z 2022-06-20T04:01:02.861Z|01608|timeval|WARN|context switches: 0 voluntary, 325 involuntary 2022-06-20T04:01:02.868688612Z 2022-06-20T04:01:02.868Z|01609|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour, hash=de9c0b02: 2022-06-20T04:01:02.870035980Z 2022-06-20T04:01:02.870Z|01610|coverage|INFO|raft_entry_serialize 0.0/sec 0.017/sec 2.3625/sec total: 9826 2022-06-20T04:01:02.871385288Z 2022-06-20T04:01:02.871Z|01611|coverage|INFO|hmap_pathological 0.0/sec 2511.517/sec 247.8633/sec total: 893856 2022-06-20T04:01:02.872711037Z 2022-06-20T04:01:02.872Z|01612|coverage|INFO|hmap_expand 1586.0/sec 25365.150/sec 7152.3728/sec total: 27443599 2022-06-20T04:01:02.874044174Z 2022-06-20T04:01:02.874Z|01613|coverage|INFO|lockfile_lock 0.0/sec 0.000/sec 0.0000/sec total: 1 2022-06-20T04:01:02.875383417Z 2022-06-20T04:01:02.875Z|01614|coverage|INFO|poll_create_node 4059.6/sec 23829.250/sec 13381.7594/sec total: 48646332 2022-06-20T04:01:02.876819310Z 2022-06-20T04:01:02.876Z|01615|coverage|INFO|poll_zero_timeout 29.4/sec 172.783/sec 26.3606/sec total: 106250 2022-06-20T04:01:02.878206020Z 2022-06-20T04:01:02.878Z|01616|coverage|INFO|seq_change 53.6/sec 300.017/sec 229.5256/sec total: 858694 2022-06-20T04:01:02.879634455Z 2022-06-20T04:01:02.879Z|01617|coverage|INFO|pstream_open 0.0/sec 0.000/sec 0.0000/sec total: 4 2022-06-20T04:01:02.881096249Z 2022-06-20T04:01:02.881Z|01618|coverage|INFO|stream_open 0.0/sec 0.000/sec 0.0014/sec total: 7 2022-06-20T04:01:02.882480677Z 2022-06-20T04:01:02.882Z|01619|coverage|INFO|unixctl_received 0.0/sec 0.117/sec 0.3236/sec total: 1814 2022-06-20T04:01:02.883911969Z 2022-06-20T04:01:02.883Z|01620|coverage|INFO|unixctl_replied 0.0/sec 0.117/sec 0.3236/sec total: 1814 2022-06-20T04:01:02.885340554Z 2022-06-20T04:01:02.885Z|01621|coverage|INFO|util_xalloc 32767.2/sec 1036770.450/sec 381007.5483/sec total: 1449512601 2022-06-20T04:01:02.886703247Z 2022-06-20T04:01:02.886Z|01622|coverage|INFO|99 events never hit 2022-06-20T04:01:02.888105896Z 2022-06-20T04:01:02.888Z|01623|poll_loop|INFO|Dropped 1679 log messages in last 40 seconds (most recently, 37 seconds ago) due to excessive rate 2022-06-20T04:01:02.892993917Z 2022-06-20T04:01:02.892Z|01624|poll_loop|INFO|wakeup due to [POLLIN] on fd 70 (10.0.145.30:9642<->10.0.158.108:41470) at ../lib/stream-ssl.c:836 (97% CPU usage) 2022-06-20T04:01:02.896308386Z 2022-06-20T04:01:02.896Z|01625|poll_loop|INFO|wakeup due to [POLLIN] on fd 59 (10.0.145.30:9642<->10.0.210.48:58644) at ../lib/stream-ssl.c:836 (97% CPU usage) 2022-06-20T04:01:02.897464131Z 2022-06-20T04:01:02.897Z|01626|poll_loop|INFO|wakeup due to [POLLIN][POLLERR][POLLHUP] on fd 25 (10.0.145.30:9642<->) at ../lib/stream-ssl.c:836 (97% CPU usage) 2022-06-20T04:01:02.898627035Z 2022-06-20T04:01:02.898Z|01627|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (97% CPU usage) 2022-06-20T04:01:02.902009448Z 2022-06-20T04:01:02.901Z|01628|poll_loop|INFO|wakeup due to [POLLIN] on fd 83 (10.0.145.30:9642<->10.0.193.166:48866) at ../lib/stream-ssl.c:836 (97% CPU usage) 2022-06-20T04:01:02.905406793Z 2022-06-20T04:01:02.905Z|01629|poll_loop|INFO|wakeup due to [POLLIN] on fd 34 (10.0.145.30:9642<->10.0.129.250:40266) at ../lib/stream-ssl.c:836 (97% CPU usage) 2022-06-20T04:01:02.915505853Z 2022-06-20T04:01:02.915Z|01630|jsonrpc|WARN|Dropped 3 log messages in last 106 seconds (most recently, 106 seconds ago) due to excessive rate 2022-06-20T04:01:02.916653470Z 2022-06-20T04:01:02.916Z|01631|jsonrpc|WARN|unix#1820: send error: Broken pipe 2022-06-20T04:01:02.920141496Z 2022-06-20T04:01:02.920Z|01632|jsonrpc|WARN|unix#1821: send error: Broken pipe 2022-06-20T04:01:02.923630643Z 2022-06-20T04:01:02.923Z|01633|jsonrpc|WARN|unix#1822: send error: Broken pipe 2022-06-20T04:01:02.927135103Z 2022-06-20T04:01:02.927Z|01634|jsonrpc|WARN|unix#1823: send error: Broken pipe 2022-06-20T04:01:02.930672652Z 2022-06-20T04:01:02.930Z|01635|jsonrpc|WARN|unix#1824: send error: Broken pipe 2022-06-20T04:01:02.948645508Z 2022-06-20T04:01:02.948Z|01636|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T04:01:02.951043449Z 2022-06-20T04:01:02.951Z|01637|stream_ssl|WARN|SSL_write: error:1409E10F:SSL routines:ssl3_write_bytes:bad length 2022-06-20T04:01:02.985618180Z 2022-06-20T04:01:02.985Z|01638|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T04:01:02.987082848Z 2022-06-20T04:01:02.987Z|01639|raft|INFO|rejected append_reply (not leader) 2022-06-20T04:01:02.988540080Z 2022-06-20T04:01:02.988Z|01640|raft|WARN|ignoring vote request received after only 1 ms (minimum election time is 16000 ms) 2022-06-20T04:01:02.989977791Z 2022-06-20T04:01:02.989Z|01641|raft|INFO|server 5869 is leader for term 39 2022-06-20T04:01:02.991350046Z 2022-06-20T04:01:02.991Z|01642|raft|INFO|8271 truncating 1 entries from end of log 2022-06-20T04:01:03.002478130Z 2022-06-20T04:01:03.002Z|01643|reconnect|WARN|ssl:10.0.192.114:44546: connection dropped (Input/output error) 2022-06-20T04:01:03.002585648Z 2022-06-20T04:01:03.002Z|01644|reconnect|WARN|ssl:10.0.171.139:49050: connection dropped (Protocol error) 2022-06-20T04:01:03.003688316Z 2022-06-20T04:01:03.003Z|01645|reconnect|INFO|ssl:10.0.192.114:9644: connection closed by peer 2022-06-20T04:01:04.005128540Z 2022-06-20T04:01:04.005Z|01646|reconnect|INFO|ssl:10.0.192.114:9644: connecting... 2022-06-20T04:01:04.011989579Z 2022-06-20T04:01:04.011Z|01647|reconnect|INFO|ssl:10.0.192.114:9644: connected 2022-06-20T04:01:05.357889413Z 2022-06-20T04:01:05.357Z|01648|poll_loop|INFO|Dropped 35 log messages in last 2 seconds (most recently, 1 seconds ago) due to excessive rate 2022-06-20T04:01:05.357944919Z 2022-06-20T04:01:05.357Z|01649|poll_loop|INFO|wakeup due to 1344-ms timeout at ../ovsdb/ovsdb-server.c:296 (97% CPU usage) 2022-06-20T04:01:08.562715624Z 2022-06-20T04:01:08.562Z|01650|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T04:01:12.337180134Z 2022-06-20T04:01:12.337Z|01651|raft|WARN|ignoring vote request received after only 9345 ms (minimum election time is 16000 ms) 2022-06-20T04:01:18.569595098Z 2022-06-20T04:01:18.569Z|01652|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T04:01:21.475113465Z 2022-06-20T04:01:21.475Z|01653|raft|INFO|rejected append_reply (not leader) 2022-06-20T04:01:21.475873585Z 2022-06-20T04:01:21.475Z|01654|raft|INFO|server 1f8e is leader for term 40 2022-06-20T04:01:28.560252321Z 2022-06-20T04:01:28.560Z|01655|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T04:01:38.571628309Z 2022-06-20T04:01:38.571Z|01656|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T04:01:40.045155177Z 2022-06-20T04:01:40.045Z|01657|raft|INFO|server 5869 is leader for term 41 2022-06-20T04:01:48.572649450Z 2022-06-20T04:01:48.572Z|01658|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T04:01:51.309271231Z 2022-06-20T04:01:51.309Z|01659|raft|INFO|rejecting term 40 < current term 41 received in append_request message from server 1f8e 2022-06-20T04:01:58.567845684Z 2022-06-20T04:01:58.567Z|01660|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T04:02:06.007299866Z 2022-06-20T04:02:06.007Z|01661|raft|INFO|term 42: 16624 ms timeout expired, starting election 2022-06-20T04:02:06.014669583Z 2022-06-20T04:02:06.014Z|01662|raft|INFO|rejecting term 41 < current term 42 received in vote_reply message from server 1f8e 2022-06-20T04:02:12.458160259Z 2022-06-20T04:02:12.458Z|01663|reconnect|ERR|ssl:10.0.171.139:9644: no response to inactivity probe after 17 seconds, disconnecting 2022-06-20T04:02:12.458289137Z 2022-06-20T04:02:12.458Z|01664|reconnect|INFO|ssl:10.0.171.139:9644: connection dropped 2022-06-20T04:02:13.460196703Z 2022-06-20T04:02:13.460Z|01665|reconnect|INFO|ssl:10.0.171.139:9644: connecting... 2022-06-20T04:02:14.067108973Z 2022-06-20T04:02:14.067Z|01666|raft|INFO|rejecting term 41 < current term 42 received in append_request message from server 5869 2022-06-20T04:02:14.143149113Z 2022-06-20T04:02:14.143Z|01667|reconnect|INFO|ssl:10.0.171.139:9644: connected 2022-06-20T04:02:16.463291221Z 2022-06-20T04:02:16.463Z|01668|poll_loop|INFO|wakeup due to [POLLIN] on fd 28 (10.0.145.30:9642<->10.0.192.114:47398) at ../lib/stream-ssl.c:825 (53% CPU usage) 2022-06-20T04:02:16.465319065Z 2022-06-20T04:02:16.465Z|01669|poll_loop|INFO|wakeup due to 0-ms timeout at ssl:10.0.192.114:47398 (53% CPU usage) 2022-06-20T04:02:16.468479659Z 2022-06-20T04:02:16.468Z|01670|poll_loop|INFO|wakeup due to 0-ms timeout at ssl:10.0.192.114:47398 (53% CPU usage) 2022-06-20T04:02:16.470643546Z 2022-06-20T04:02:16.470Z|01671|poll_loop|INFO|wakeup due to [POLLIN] on fd 28 (10.0.145.30:9642<->10.0.192.114:47398) at ../lib/stream-ssl.c:836 (53% CPU usage) 2022-06-20T04:02:16.472539213Z 2022-06-20T04:02:16.472Z|01672|poll_loop|INFO|wakeup due to 0-ms timeout at ssl:10.0.192.114:47398 (53% CPU usage) 2022-06-20T04:02:16.474380660Z 2022-06-20T04:02:16.474Z|01673|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (53% CPU usage) 2022-06-20T04:02:16.477136131Z 2022-06-20T04:02:16.477Z|01674|poll_loop|INFO|wakeup due to 0-ms timeout at ssl:10.0.192.114:47398 (53% CPU usage) 2022-06-20T04:02:16.479198013Z 2022-06-20T04:02:16.479Z|01675|poll_loop|INFO|wakeup due to 0-ms timeout at ../lib/stream-ssl.c:814 (53% CPU usage) 2022-06-20T04:02:16.480847642Z 2022-06-20T04:02:16.480Z|01676|poll_loop|INFO|wakeup due to 0-ms timeout at ssl:10.0.171.139:51550 (53% CPU usage) 2022-06-20T04:02:16.484015003Z 2022-06-20T04:02:16.483Z|01677|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (53% CPU usage) 2022-06-20T04:02:22.426372615Z 2022-06-20T04:02:22.426Z|01678|raft|INFO|term 43: 16418 ms timeout expired, starting election 2022-06-20T04:02:22.437182183Z 2022-06-20T04:02:22.437Z|01679|raft|INFO|rejecting term 41 < current term 43 received in vote_reply message from server 1f8e 2022-06-20T04:02:22.468050954Z 2022-06-20T04:02:22.468Z|01680|poll_loop|INFO|Dropped 1902 log messages in last 6 seconds (most recently, 0 seconds ago) due to excessive rate 2022-06-20T04:02:22.468078796Z 2022-06-20T04:02:22.468Z|01681|poll_loop|INFO|wakeup due to [POLLIN] on fd 28 (10.0.145.30:9642<->10.0.171.139:52570) at ../lib/stream-ssl.c:825 (81% CPU usage) 2022-06-20T04:02:23.315000063Z 2022-06-20T04:02:23.314Z|01682|raft|INFO|8271 received "lost leadership" reply from 1f8e for unknown command 2022-06-20T04:02:30.804700737Z 2022-06-20T04:02:30.804Z|01683|raft|INFO|rejecting term 42 < current term 43 received in vote_request message from server 1f8e 2022-06-20T04:02:30.805308951Z 2022-06-20T04:02:30.805Z|01684|raft|INFO|rejecting term 42 < current term 43 received in append_request message from server 1f8e 2022-06-20T04:02:38.517990391Z 2022-06-20T04:02:38.517Z|01685|raft|INFO|term 44: 16091 ms timeout expired, starting election 2022-06-20T04:02:38.521398152Z 2022-06-20T04:02:38.521Z|01686|raft|INFO|rejecting term 42 < current term 44 received in vote_reply message from server 5869 2022-06-20T04:02:46.066800497Z 2022-06-20T04:02:46.066Z|01687|raft|INFO|8271 received "lost leadership" reply from 5869 for unknown command 2022-06-20T04:02:47.239217092Z 2022-06-20T04:02:47.239Z|01688|raft|INFO|rejecting term 43 < current term 44 received in vote_request message from server 5869 2022-06-20T04:02:47.244971533Z 2022-06-20T04:02:47.244Z|01689|raft|INFO|rejecting term 43 < current term 44 received in append_request message from server 5869 2022-06-20T04:02:54.669159820Z 2022-06-20T04:02:54.669Z|01690|raft|INFO|term 45: 16151 ms timeout expired, starting election 2022-06-20T04:02:54.671931091Z 2022-06-20T04:02:54.671Z|01691|raft|INFO|rejecting term 43 < current term 45 received in vote_reply message from server 1f8e 2022-06-20T04:03:03.265613709Z 2022-06-20T04:03:03.265Z|01692|raft|INFO|server 5869 is leader for term 45 2022-06-20T04:03:03.265661981Z 2022-06-20T04:03:03.265Z|01693|raft|INFO|rejecting append_request because previous entry 43,9931 not in local log (mismatch past end of log) 2022-06-20T04:03:08.554261235Z 2022-06-20T04:03:08.554Z|01694|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T04:03:18.568300987Z 2022-06-20T04:03:18.568Z|01695|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T04:03:25.568423331Z 2022-06-20T04:03:25.568Z|01696|raft|INFO|server 1f8e is leader for term 46 2022-06-20T04:03:28.559611783Z 2022-06-20T04:03:28.559Z|01697|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T04:03:36.128537115Z 2022-06-20T04:03:36.128Z|01698|raft|INFO|rejecting term 45 < current term 46 received in append_request message from server 5869 2022-06-20T04:03:38.561965022Z 2022-06-20T04:03:38.561Z|01699|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T04:03:42.352964427Z 2022-06-20T04:03:42.352Z|01700|raft|INFO|term 47: 16782 ms timeout expired, starting election 2022-06-20T04:03:42.357567686Z 2022-06-20T04:03:42.357Z|01701|raft|INFO|rejecting term 46 < current term 47 received in vote_reply message from server 5869 2022-06-20T04:03:50.351989860Z 2022-06-20T04:03:50.351Z|01702|reconnect|ERR|ssl:10.0.192.114:9644: no response to inactivity probe after 17 seconds, disconnecting 2022-06-20T04:03:50.352065757Z 2022-06-20T04:03:50.352Z|01703|reconnect|INFO|ssl:10.0.192.114:9644: connection dropped 2022-06-20T04:03:51.353533458Z 2022-06-20T04:03:51.353Z|01704|reconnect|INFO|ssl:10.0.192.114:9644: connecting... 2022-06-20T04:03:52.353675158Z 2022-06-20T04:03:52.353Z|01705|reconnect|INFO|ssl:10.0.192.114:9644: connection attempt timed out 2022-06-20T04:03:52.353728875Z 2022-06-20T04:03:52.353Z|01706|reconnect|INFO|ssl:10.0.192.114:9644: waiting 2 seconds before reconnect 2022-06-20T04:03:53.327415996Z 2022-06-20T04:03:53.327Z|01707|raft|INFO|rejecting term 46 < current term 47 received in vote_reply message from server 1f8e 2022-06-20T04:03:53.385680153Z 2022-06-20T04:03:53.385Z|01708|raft|INFO|rejecting term 46 < current term 47 received in append_request message from server 1f8e 2022-06-20T04:03:53.387029085Z 2022-06-20T04:03:53.387Z|01709|raft|INFO|rejecting term 46 < current term 47 received in become_leader message from server 1f8e 2022-06-20T04:03:54.354567527Z 2022-06-20T04:03:54.354Z|01710|reconnect|INFO|ssl:10.0.192.114:9644: connecting... 2022-06-20T04:03:56.354922644Z 2022-06-20T04:03:56.354Z|01711|reconnect|INFO|ssl:10.0.192.114:9644: connection attempt timed out 2022-06-20T04:03:56.355013551Z 2022-06-20T04:03:56.354Z|01712|reconnect|INFO|ssl:10.0.192.114:9644: waiting 4 seconds before reconnect 2022-06-20T04:03:59.123112052Z 2022-06-20T04:03:59.123Z|01713|raft|INFO|rejecting term 46 < current term 48 received in vote_reply message from server 5869 2022-06-20T04:04:00.356618463Z 2022-06-20T04:04:00.356Z|01714|reconnect|INFO|ssl:10.0.192.114:9644: connecting... 2022-06-20T04:04:04.356920024Z 2022-06-20T04:04:04.356Z|01715|reconnect|INFO|ssl:10.0.192.114:9644: connection attempt timed out 2022-06-20T04:04:04.357008842Z 2022-06-20T04:04:04.356Z|01716|reconnect|INFO|ssl:10.0.192.114:9644: continuing to reconnect in the background but suppressing further logging 2022-06-20T04:04:09.828586459Z 2022-06-20T04:04:09.828Z|01717|raft|INFO|rejecting term 47 < current term 48 received in vote_request message from server 5869 2022-06-20T04:04:15.540649984Z 2022-06-20T04:04:15.540Z|01718|raft|INFO|term 49: elected leader by 2+ of 3 servers 2022-06-20T04:04:18.060098721Z 2022-06-20T04:04:18.060Z|01719|raft|INFO|Dropped 30 log messages in last 195 seconds (most recently, 195 seconds ago) due to excessive rate 2022-06-20T04:04:18.060135597Z 2022-06-20T04:04:18.060Z|01720|raft|INFO|current entry eid c6835731-1564-4bf3-a3e2-77aeedbd9b87 does not match prerequisite 244846a0-35a6-4352-8eb2-2174e160f731 in execute_command_request 2022-06-20T04:04:18.569577215Z 2022-06-20T04:04:18.569Z|01721|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T04:04:18.874033925Z 2022-06-20T04:04:18.873Z|01722|raft|INFO|current entry eid 323adb73-d8bc-495e-a6eb-070996640227 does not match prerequisite c574dddb-487e-4c9f-8fc4-dcaef93deb07 in execute_command_request 2022-06-20T04:04:18.874109817Z 2022-06-20T04:04:18.874Z|01723|raft|INFO|current entry eid 323adb73-d8bc-495e-a6eb-070996640227 does not match prerequisite c574dddb-487e-4c9f-8fc4-dcaef93deb07 in execute_command_request 2022-06-20T04:04:18.874177222Z 2022-06-20T04:04:18.874Z|01724|raft|INFO|current entry eid 323adb73-d8bc-495e-a6eb-070996640227 does not match prerequisite c574dddb-487e-4c9f-8fc4-dcaef93deb07 in execute_command_request 2022-06-20T04:04:18.874249997Z 2022-06-20T04:04:18.874Z|01725|raft|INFO|current entry eid 323adb73-d8bc-495e-a6eb-070996640227 does not match prerequisite c574dddb-487e-4c9f-8fc4-dcaef93deb07 in execute_command_request 2022-06-20T04:04:18.882505986Z 2022-06-20T04:04:18.882Z|01726|raft|INFO|rejecting term 48 < current term 49 received in vote_reply message from server 1f8e 2022-06-20T04:04:18.882746788Z 2022-06-20T04:04:18.882Z|01727|raft|INFO|rejecting term 48 < current term 49 received in vote_reply message from server 1f8e 2022-06-20T04:04:18.902068246Z 2022-06-20T04:04:18.902Z|01728|reconnect|INFO|ssl:10.0.192.114:9644: connected 2022-06-20T04:04:42.980466681Z 2022-06-20T04:04:42.980Z|01729|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T04:04:42.982372549Z 2022-06-20T04:04:42.982Z|01730|jsonrpc|WARN|Dropped 5 log messages in last 220 seconds (most recently, 220 seconds ago) due to excessive rate 2022-06-20T04:04:42.984208676Z 2022-06-20T04:04:42.984Z|01731|jsonrpc|WARN|ssl:10.0.145.30:38610: send error: Broken pipe 2022-06-20T04:04:43.036146013Z 2022-06-20T04:04:43.036Z|01732|raft|WARN|ignoring vote request received as leader 2022-06-20T04:04:43.052051261Z 2022-06-20T04:04:43.052Z|01733|raft|INFO|server 1f8e is leader for term 50 2022-06-20T04:04:43.170348422Z 2022-06-20T04:04:43.170Z|01734|raft|INFO|rejecting term 49 < current term 50 received in append_reply message from server 5869 2022-06-20T04:04:43.271524302Z 2022-06-20T04:04:43.271Z|01735|timeval|WARN|Unreasonably long 24090ms poll interval (23688ms user, 118ms system) 2022-06-20T04:04:43.271570179Z 2022-06-20T04:04:43.271Z|01736|timeval|WARN|faults: 1978 minor, 0 major 2022-06-20T04:04:43.271579409Z 2022-06-20T04:04:43.271Z|01737|timeval|WARN|disk: 0 reads, 152 writes 2022-06-20T04:04:43.271598421Z 2022-06-20T04:04:43.271Z|01738|timeval|WARN|context switches: 5 voluntary, 343 involuntary 2022-06-20T04:04:43.271628182Z 2022-06-20T04:04:43.271Z|01739|coverage|INFO|Skipping details of duplicate event coverage for hash=de9c0b02 2022-06-20T04:04:43.271652722Z 2022-06-20T04:04:43.271Z|01740|poll_loop|INFO|Dropped 1396 log messages in last 141 seconds (most recently, 138 seconds ago) due to excessive rate 2022-06-20T04:04:43.271670414Z 2022-06-20T04:04:43.271Z|01741|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (96% CPU usage) 2022-06-20T04:04:43.271697299Z 2022-06-20T04:04:43.271Z|01742|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (96% CPU usage) 2022-06-20T04:04:43.271809612Z 2022-06-20T04:04:43.271Z|01743|jsonrpc|WARN|unix#1885: send error: Broken pipe 2022-06-20T04:04:43.271861610Z 2022-06-20T04:04:43.271Z|01744|jsonrpc|WARN|unix#1887: send error: Broken pipe 2022-06-20T04:04:43.271901725Z 2022-06-20T04:04:43.271Z|01745|jsonrpc|WARN|unix#1888: send error: Broken pipe 2022-06-20T04:04:43.272014929Z 2022-06-20T04:04:43.271Z|01746|stream_ssl|WARN|SSL_write: system error (Connection reset by peer) 2022-06-20T04:04:43.272027657Z 2022-06-20T04:04:43.272Z|01747|jsonrpc|WARN|ssl:10.0.171.139:33590: send error: Connection reset by peer 2022-06-20T04:04:43.272289464Z 2022-06-20T04:04:43.272Z|01748|reconnect|WARN|ssl:10.0.145.30:38610: connection dropped (Broken pipe) 2022-06-20T04:04:43.274022154Z 2022-06-20T04:04:43.273Z|01749|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T04:04:43.278931741Z 2022-06-20T04:04:43.278Z|01750|raft|INFO|rejected append_reply (not leader) 2022-06-20T04:04:43.280240844Z 2022-06-20T04:04:43.280Z|01751|raft|INFO|rejected append_reply (not leader) 2022-06-20T04:04:43.281659197Z 2022-06-20T04:04:43.281Z|01752|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (96% CPU usage) 2022-06-20T04:04:43.281804617Z 2022-06-20T04:04:43.281Z|01753|reconnect|WARN|ssl:10.0.171.139:33590: connection dropped (Connection reset by peer) 2022-06-20T04:04:43.281969808Z 2022-06-20T04:04:43.281Z|01754|reconnect|WARN|ssl:10.0.145.30:38620: connection dropped (Protocol error) 2022-06-20T04:04:43.283104673Z 2022-06-20T04:04:43.283Z|01755|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T04:04:43.284140020Z 2022-06-20T04:04:43.284Z|01756|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (96% CPU usage) 2022-06-20T04:04:43.284788965Z 2022-06-20T04:04:43.284Z|01757|reconnect|WARN|ssl:10.0.171.139:33716: connection dropped (Protocol error) 2022-06-20T04:04:43.285868297Z 2022-06-20T04:04:43.285Z|01758|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T04:04:43.285960897Z 2022-06-20T04:04:43.285Z|01759|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (96% CPU usage) high CPU usage on SBDB
Current cluster where we see pods stuck on container creating: QPS=20, 120 nodes, 1500 routes, 2000 services, 3000 pods. 4.11.0-0.nightly-2022-06-15-222801 auth/console/monitoring degraded. -> auth is degraded because of failing health checks: clusteroperator/authentication is not available (OAuthServerRouteEndpointAccessibleControllerAvailable: Get "https://oauth-openshift.apps.qili-awsovn-surya.qe.devclu ster.openshift.com/healthz": EOF) because OAuthServerRouteEndpointAccessibleControllerDegraded: Get "https://oauth-openshift.apps.qili-awsovn-surya.qe.devcluster.openshift.c om/healthz": EOF clusteroperator/monitoring is not available (Rollout of the monitoring stack failed and is degraded. Please investigate the degraded status error.) because Failed to rollout the stack. Error: updating prometheus operator: reconciling Prometheus Operator Admission Webhook Deployment failed: updating Deployment object failed: waiting for DeploymentRollout of openshift-monitoring/prometheus-operator-admission-webhook: the number of pods targeted by the deployment (3 pods) is different from the number of pods targeted by the deployment that have the desired template spec (2 pods) We have several test pods stuck in containerCreating, beyond a certain point cluster gets unstable, no new pods can be created beyond this point. $ oc get pods -A -owide | grep ContainerCreating | wc -l 506 http-scale-passthrough http-perf-86-68f85964b6-7ghwj 0/1 ContainerCreating 0 106m <none> ip-10-0-212-123.us-east-2.compute.internal <none> <none> http-scale-passthrough http-perf-87-d5f5d5477-fkzvr 0/1 ContainerCreating 0 105m <none> ip-10-0-162-156.us-east-2.compute.internal <none> <none> http-scale-passthrough http-perf-88-bf6c44b9b-gcrzh 0/1 ContainerCreating 0 105m <none> ip-10-0-169-226.us-east-2.compute.internal <none> <none> http-scale-passthrough http-perf-89-6699885c75-2lqjk 0/1 ContainerCreating 0 106m <none> ip-10-0-181-240.us-east-2.compute.internal <none> <none> http-scale-passthrough http-perf-9-7f9fdfbb6f-bcvwf 0/1 ContainerCreating 0 106m <none> ip-10-0-212-123.us-east-2.compute.internal <none> <none> http-scale-passthrough http-perf-90-548cbb7449-sp4pd 0/1 ContainerCreating 0 106m <none> ip-10-0-139-143.us-east-2.compute.internal <none> <none> http-scale-passthrough http-perf-91-79fcf48558-6vkrm 0/1 ContainerCreating 0 106m <none> ip-10-0-142-74.us-east-2.compute.internal <none> <none> http-scale-passthrough http-perf-92-6f58ff6c8c-scrkc 0/1 ContainerCreating 0 106m <none> ip-10-0-169-52.us-east-2.compute.internal <none> <none> http-scale-passthrough http-perf-93-599bc9ccd8-jhfwn 0/1 ContainerCreating 0 106m <none> ip-10-0-181-240.us-east-2.compute.internal <none> <none> http-scale-passthrough http-perf-94-646859c77c-vddn5 0/1 ContainerCreating 0 106m <none> ip-10-0-139-143.us-east-2.compute.internal <none> <none> http-scale-passthrough http-perf-95-6d9bf6f54-frqq2 0/1 ContainerCreating 0 106m <none> ip-10-0-142-74.us-east-2.compute.internal <none> <none> http-scale-passthrough http-perf-96-7d95f8bd7f-f44jb 0/1 ContainerCreating 0 105m <none> ip-10-0-154-173.us-east-2.compute.internal <none> <none> http-scale-passthrough http-perf-97-58c68cb95b-62qbn 0/1 ContainerCreating 0 106m <none> ip-10-0-176-221.us-east-2.compute.internal <none> <none> http-scale-passthrough http-perf-98-55c5c55b65-jwf5t 0/1 ContainerCreating 0 106m <none> ip-10-0-148-53.us-east-2.compute.internal <none> So picking one pod from this group: http-perf-96-7d95f8bd7f-f44jb ovnkube-master: sh-4.4# cat 3.log.20220620-150705 | grep http-perf-96-7d95f8bd7f-f44jb 2022-06-20T14:52:24.157549332+00:00 stderr F I0620 14:52:24.157533 1 obj_retry.go:1364] Creating *v1.Pod http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb took: 236ns 2022-06-20T14:52:24.157566806+00:00 stderr F I0620 14:52:24.157559 1 obj_retry.go:1465] Updating *v1.Pod http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb 2022-06-20T14:52:24.157577034+00:00 stderr F I0620 14:52:24.157567 1 pods.go:364] [http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb] creating logical port for pod on switch ip-10-0-154-173.us-east-2.compute.internal 2022-06-20T14:52:24.157665171+00:00 stderr F I0620 14:52:24.157646 1 kube.go:73] Setting annotations map[k8s.ovn.org/pod-networks:{"default":{"ip_addresses":["10.129.12.17/23"],"mac_address":"0a:58:0a:81:0c:11","gateway_ips":["10.129.12.1"],"ip_address":"10.129.12.17/23","gateway_ip":"10.129.12.1"}}] on pod http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb 2022-06-20T14:52:24.205978732+00:00 stderr F I0620 14:52:24.205887 1 transact.go:41] Configuring OVN: [{Op:mutate Table:Address_Set Row:map[] Rows:[] Columns:[] Mutations:[{Column:addresses Mutator:insert Value:{GoSet:[10.129.12.17]}}] Timeout:<nil> Where:[where column _uuid == {73c8e5ed-7838-4370-a600-1fbebf580b4f}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:} {Op:insert Table:NAT Row:map[external_ip:10.0.154.173 logical_ip:10.129.12.17 options:{GoMap:map[stateless:false]} type:snat] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2597161880} {Op:mutate Table:Logical_Router Row:map[] Rows:[] Columns:[] Mutations:[{Column:nat Mutator:insert Value:{GoSet:[{GoUUID:u2597161880}]}}] Timeout:<nil> Where:[where column _uuid == {0828db9c-baeb-4198-9017-3cc37363cf7e}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:} {Op:insert Table:Logical_Switch_Port Row:map[addresses:{GoSet:[0a:58:0a:81:0c:11 10.129.12.17]} external_ids:{GoMap:map[namespace:http-scale-passthrough pod:true]} name:http-scale-passthrough_http-perf-96-7d95f8bd7f-f44jb options:{GoMap:map[iface-id-ver:6d50c4d8-9075-4ba4-8ade-661f7895ba96 requested-chassis:ip-10-0-154-173.us-east-2.compute.internal]} port_security:{GoSet:[0a:58:0a:81:0c:11 10.129.12.17]}] Rows:[] Columns:[] Mutations:[] Timeout:<nil> Where:[] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:u2597161881} {Op:mutate Table:Logical_Switch Row:map[] Rows:[] Columns:[] Mutations:[{Column:ports Mutator:insert Value:{GoSet:[{GoUUID:u2597161881}]}}] Timeout:<nil> Where:[where column _uuid == {d1aae134-bf07-4e23-8f02-cf7e6e084eca}] Until: Durable:<nil> Comment:<nil> Lock:<nil> UUIDName:}] 2022-06-20T14:52:29.276946866+00:00 stderr F I0620 14:52:29.276910 1 pods.go:353] [http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb] addLogicalPort took 5.119340233s, libovsdb time 5.07101286s, annotation time: 47.771703ms ovnkube-node: even if the add came a few seconds before annotation was set, it was within the timeout period though I0620 14:52:15.855013 3592 cni.go:227] [http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb dbe2f667d80ee679b3ea044700bd851fbc5e7bc09e147ad668b6376f657fd362] ADD starting CNI request [http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb dbe2f667d80ee679b3ea044700bd851fbc5e7bc09e147ad668b6376f657fd362] I0620 14:52:24.296486 3592 helper_linux.go:249] ConfigureOVS: namespace: http-scale-passthrough, podName: http-perf-96-7d95f8bd7f-f44jb W0620 14:54:15.904053 3592 helper_linux.go:309] [http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb dbe2f667d80ee679b3ea044700bd851fbc5e7bc09e147ad668b6376f657fd362] pod uid 6d50c4d8-9075-4ba4-8ade-661f7895ba96: timed out waiting for OVS port binding (ovn-installed) for 0a:58:0a:81:0c:11 [10.129.12.17/23] I0620 14:54:16.076968 3592 cni.go:248] [http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb dbe2f667d80ee679b3ea044700bd851fbc5e7bc09e147ad668b6376f657fd362] ADD finished CNI request [http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb dbe2f667d80ee679b3ea044700bd851fbc5e7bc09e147ad668b6376f657fd362], result "", err failed to configure pod interface: timed out waiting for OVS port binding (ovn-installed) for 0a:58:0a:81:0c:11 [10.129.12.17/23] I0620 14:54:16.193891 3592 cni.go:227] [http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb dbe2f667d80ee679b3ea044700bd851fbc5e7bc09e147ad668b6376f657fd362] DEL starting CNI request [http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb dbe2f667d80ee679b3ea044700bd851fbc5e7bc09e147ad668b6376f657fd362] W0620 14:54:16.210003 3592 helper_linux.go:490] Failed to delete pod "http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb" interface dbe2f667d80ee67: failed to lookup link dbe2f667d80ee67: Link not found I0620 14:54:16.233079 3592 cni.go:248] [http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb dbe2f667d80ee679b3ea044700bd851fbc5e7bc09e147ad668b6376f657fd362] DEL finished CNI request [http-scale-passthrough/http-perf-96-7d95f8bd7f-f44jb dbe2f667d80ee679b3ea044700bd851fbc5e7bc09e147ad668b6376f657fd362], result "{\"dns\":{}}", err <nil> ovn-controller: 2022-06-20T14:47:39.860Z|00239|poll_loop|INFO|Dropped 157 log messages in last 24 seconds (most recently, 22 seconds ago) due to excessive rate 2022-06-20T14:47:39.860Z|00240|poll_loop|INFO|wakeup due to [POLLIN][POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (62% CPU usage) 2022-06-20T14:47:39.860Z|00241|poll_loop|INFO|wakeup due to [POLLIN] on fd 19 (10.0.154.173:52318<->10.0.157.93:9642) at lib/stream-ssl.c:836 (62% CPU usage) 2022-06-20T14:47:39.891Z|00242|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (62% CPU usage) 2022-06-20T14:47:39.901Z|00243|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (62% CPU usage) 2022-06-20T14:47:54.467Z|00244|timeval|WARN|Unreasonably long 1213ms poll interval (1202ms user, 2ms system) 2022-06-20T14:47:54.467Z|00245|timeval|WARN|faults: 530 minor, 0 major 2022-06-20T14:47:54.467Z|00246|timeval|WARN|context switches: 0 voluntary, 5 involuntary 2022-06-20T14:47:54.527Z|00247|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour, hash=5fabe473: 2022-06-20T14:47:54.527Z|00248|coverage|INFO|lflow_run 0.0/sec 0.000/sec 0.0053/sec total: 19 2022-06-20T14:47:54.527Z|00249|coverage|INFO|consider_logical_flow 0.0/sec 3163.600/sec 154.5286/sec total: 583439 2022-06-20T14:47:54.527Z|00250|coverage|INFO|lflow_cache_add_expr 0.0/sec 4.767/sec 1.0033/sec total: 3612 2022-06-20T14:47:54.527Z|00251|coverage|INFO|lflow_cache_add_matches 0.0/sec 49.167/sec 2.3783/sec total: 8986 2022-06-20T14:47:54.527Z|00252|coverage|INFO|lflow_cache_free_expr 0.0/sec 0.017/sec 0.0100/sec total: 37 2022-06-20T14:47:54.527Z|00253|coverage|INFO|lflow_cache_free_matches 0.0/sec 3.467/sec 0.7878/sec total: 3260 2022-06-20T14:47:54.527Z|00254|coverage|INFO|lflow_cache_add 0.0/sec 53.933/sec 3.3817/sec total: 12598 2022-06-20T14:47:54.527Z|00255|coverage|INFO|lflow_cache_hit 0.0/sec 3.483/sec 23.9372/sec total: 86599 2022-06-20T14:47:54.527Z|00256|coverage|INFO|lflow_cache_miss 0.0/sec 494.350/sec 20.6789/sec total: 128725 2022-06-20T14:47:54.527Z|00257|coverage|INFO|lflow_cache_delete 0.0/sec 3.483/sec 0.7978/sec total: 3297 2022-06-20T14:47:54.527Z|00258|coverage|INFO|lflow_cache_trim 0.0/sec 0.000/sec 0.0008/sec total: 3 2022-06-20T14:47:54.527Z|00259|coverage|INFO|pinctrl_notify_main_thread 0.0/sec 0.017/sec 0.0886/sec total: 319 2022-06-20T14:47:54.527Z|00260|coverage|INFO|pinctrl_total_pin_pkts 0.0/sec 0.017/sec 0.1739/sec total: 626 2022-06-20T14:47:54.527Z|00261|coverage|INFO|physical_run 0.0/sec 0.000/sec 0.0067/sec total: 24 2022-06-20T14:47:54.527Z|00262|coverage|INFO|flow_extract 0.0/sec 0.017/sec 0.1739/sec total: 626 2022-06-20T14:47:54.527Z|00263|coverage|INFO|miniflow_malloc 0.0/sec 149.033/sec 57.0397/sec total: 206827 2022-06-20T14:47:54.527Z|00264|coverage|INFO|hmap_pathological 36.4/sec 126.967/sec 6.9475/sec total: 25593 2022-06-20T14:47:54.527Z|00265|coverage|INFO|hmap_expand 865.6/sec 7662.700/sec 328.4792/sec total: 1236077 2022-06-20T14:47:54.527Z|00266|coverage|INFO|txn_unchanged 10.4/sec 28.900/sec 2.1564/sec total: 7919 2022-06-20T14:47:54.527Z|00267|coverage|INFO|txn_incomplete 0.0/sec 6.700/sec 0.4339/sec total: 1562 2022-06-20T14:47:54.527Z|00268|coverage|INFO|txn_success 0.0/sec 0.150/sec 0.0172/sec total: 62 2022-06-20T14:47:54.527Z|00269|coverage|INFO|txn_try_again 0.0/sec 0.000/sec 0.0006/sec total: 2 2022-06-20T14:47:54.527Z|00270|coverage|INFO|poll_create_node 109.2/sec 335.650/sec 27.2125/sec total: 99478 2022-06-20T14:47:54.527Z|00271|coverage|INFO|poll_zero_timeout 0.0/sec 8.567/sec 0.2417/sec total: 942 2022-06-20T14:47:54.527Z|00272|coverage|INFO|rconn_queued 0.0/sec 83.567/sec 8.3775/sec total: 31435 2022-06-20T14:47:54.527Z|00273|coverage|INFO|rconn_sent 0.0/sec 83.567/sec 8.3775/sec total: 30523 2022-06-20T14:47:54.527Z|00274|coverage|INFO|seq_change 48.6/sec 144.800/sec 11.7042/sec total: 42774 2022-06-20T14:47:54.527Z|00275|coverage|INFO|pstream_open 0.0/sec 0.000/sec 0.0003/sec total: 1 2022-06-20T14:47:54.527Z|00276|coverage|INFO|stream_open 0.0/sec 0.000/sec 0.0017/sec total: 6 2022-06-20T14:47:54.527Z|00277|coverage|INFO|unixctl_received 0.0/sec 0.033/sec 0.0025/sec total: 9 2022-06-20T14:47:54.527Z|00278|coverage|INFO|unixctl_replied 0.0/sec 0.033/sec 0.0025/sec total: 9 2022-06-20T14:47:54.527Z|00279|coverage|INFO|util_xalloc 18282.4/sec 375133.633/sec 14215.1342/sec total: 54100633 2022-06-20T14:47:54.527Z|00280|coverage|INFO|vconn_open 0.0/sec 0.000/sec 0.0008/sec total: 3 2022-06-20T14:47:54.527Z|00281|coverage|INFO|vconn_received 0.0/sec 0.233/sec 0.5214/sec total: 1877 2022-06-20T14:47:54.527Z|00282|coverage|INFO|vconn_sent 0.0/sec 83.867/sec 8.4083/sec total: 30635 2022-06-20T14:47:54.527Z|00283|coverage|INFO|netlink_received 4.2/sec 8.300/sec 0.7281/sec total: 2624 2022-06-20T14:47:54.527Z|00284|coverage|INFO|netlink_recv_jumbo 1.4/sec 2.767/sec 0.2422/sec total: 873 2022-06-20T14:47:54.527Z|00285|coverage|INFO|netlink_sent 4.2/sec 8.300/sec 0.7281/sec total: 2624 2022-06-20T14:47:54.527Z|00286|coverage|INFO|cmap_expand 0.0/sec 0.000/sec 0.0008/sec total: 3 2022-06-20T14:47:54.527Z|00287|coverage|INFO|101 events never hit 2022-06-20T14:48:07.008Z|00288|timeval|WARN|Unreasonably long 1102ms poll interval (1093ms user, 0ms system) 2022-06-20T14:48:07.008Z|00289|timeval|WARN|context switches: 0 voluntary, 6 involuntary 2022-06-20T14:49:08.954Z|00290|lflow_cache|INFO|Detected cache inactivity (last active 30004 ms ago): trimming cache 2022-06-20T14:50:19.622Z|00291|inc_proc_eng|INFO|node: logical_flow_output, handler for input SB_logical_flow took 613ms 2022-06-20T14:50:19.784Z|00292|timeval|WARN|Unreasonably long 5653ms poll interval (5452ms user, 154ms system) 2022-06-20T14:50:19.784Z|00293|timeval|WARN|faults: 85640 minor, 0 major 2022-06-20T14:50:19.784Z|00294|timeval|WARN|context switches: 0 voluntary, 12 involuntary 2022-06-20T14:50:19.784Z|00295|coverage|INFO|Dropped 1 log messages in last 133 seconds (most recently, 133 seconds ago) due to excessive rate 2022-06-20T14:50:19.812Z|00296|coverage|INFO|Event coverage, avg rate over last: 5 seconds, last minute, last hour, hash=134c8314: 2022-06-20T14:50:19.812Z|00297|coverage|INFO|lflow_run 0.0/sec 0.000/sec 0.0053/sec total: 19 2022-06-20T14:50:19.812Z|00298|coverage|INFO|consider_logical_flow 0.0/sec 0.000/sec 173.6019/sec total: 852179 2022-06-20T14:50:19.812Z|00299|coverage|INFO|lflow_cache_add_expr 0.0/sec 0.000/sec 1.0633/sec total: 4112 2022-06-20T14:50:19.812Z|00300|coverage|INFO|lflow_cache_add_matches 0.0/sec 0.000/sec 2.6717/sec total: 13146 2022-06-20T14:50:19.812Z|00301|coverage|INFO|lflow_cache_free_expr 0.0/sec 0.000/sec 0.0103/sec total: 37 2022-06-20T14:50:19.812Z|00302|coverage|INFO|lflow_cache_free_matches 0.0/sec 0.000/sec 1.0144/sec total: 3652 2022-06-20T14:50:19.812Z|00303|coverage|INFO|lflow_cache_add 0.0/sec 0.000/sec 3.7350/sec total: 17258 2022-06-20T14:50:19.812Z|00304|coverage|INFO|lflow_cache_hit 0.0/sec 0.000/sec 24.1642/sec total: 86991 2022-06-20T14:50:19.812Z|00305|coverage|INFO|lflow_cache_miss 0.0/sec 0.000/sec 49.8214/sec total: 183169 2022-06-20T14:50:19.812Z|00306|coverage|INFO|lflow_cache_delete 0.0/sec 0.000/sec 1.0247/sec total: 3689 2022-06-20T14:50:19.812Z|00307|coverage|INFO|lflow_cache_trim 0.0/sec 0.017/sec 0.0011/sec total: 4 2022-06-20T14:50:19.812Z|00308|coverage|INFO|pinctrl_notify_main_thread 0.0/sec 0.000/sec 0.0889/sec total: 320 2022-06-20T14:50:19.812Z|00309|coverage|INFO|pinctrl_total_pin_pkts 0.0/sec 0.000/sec 0.1742/sec total: 627 2022-06-20T14:50:19.812Z|00310|coverage|INFO|physical_run 0.0/sec 0.000/sec 0.0067/sec total: 24 2022-06-20T14:50:19.812Z|00311|coverage|INFO|flow_extract 0.0/sec 0.000/sec 0.1742/sec total: 627 2022-06-20T14:50:19.812Z|00312|coverage|INFO|miniflow_malloc 0.0/sec 0.000/sec 58.1431/sec total: 219435 2022-06-20T14:50:19.812Z|00313|coverage|INFO|hmap_pathological 870.6/sec 77.567/sec 9.7228/sec total: 35077 2022-06-20T14:50:19.812Z|00314|coverage|INFO|hmap_expand 76235.8/sec 6470.467/sec 498.7325/sec total: 1856318 2022-06-20T14:50:19.812Z|00315|coverage|INFO|txn_unchanged 247.6/sec 22.067/sec 2.8292/sec total: 10197 2022-06-20T14:50:19.812Z|00316|coverage|INFO|txn_incomplete 0.0/sec 0.000/sec 0.5389/sec total: 1940 2022-06-20T14:50:19.812Z|00317|coverage|INFO|txn_success 0.0/sec 0.000/sec 0.0192/sec total: 69 2022-06-20T14:50:19.812Z|00318|coverage|INFO|txn_try_again 0.0/sec 0.000/sec 0.0006/sec total: 2 2022-06-20T14:50:19.812Z|00319|coverage|INFO|poll_create_node 2483.2/sec 224.200/sec 34.9264/sec total: 125791 2022-06-20T14:50:19.812Z|00320|coverage|INFO|poll_zero_timeout 122.8/sec 10.233/sec 0.4631/sec total: 1672 2022-06-20T14:50:19.812Z|00321|coverage|INFO|rconn_queued 0.2/sec 0.050/sec 9.2325/sec total: 38666 2022-06-20T14:50:19.812Z|00322|coverage|INFO|rconn_sent 0.2/sec 0.050/sec 9.2325/sec total: 33638 2022-06-20T14:50:19.812Z|00323|coverage|INFO|seq_change 1055.8/sec 95.117/sec 15.0067/sec total: 54045 2022-06-20T14:50:19.812Z|00324|coverage|INFO|pstream_open 0.0/sec 0.000/sec 0.0003/sec total: 1 2022-06-20T14:50:19.812Z|00325|coverage|INFO|stream_open 0.0/sec 0.000/sec 0.0017/sec total: 6 2022-06-20T14:50:19.812Z|00326|coverage|INFO|unixctl_received 0.0/sec 0.000/sec 0.0025/sec total: 9 2022-06-20T14:50:19.812Z|00327|coverage|INFO|unixctl_replied 0.0/sec 0.000/sec 0.0025/sec total: 9 2022-06-20T14:50:19.812Z|00328|coverage|INFO|util_xalloc 3230075.6/sec 271652.400/sec 21301.8083/sec total: 85355819 2022-06-20T14:50:19.812Z|00329|coverage|INFO|vconn_open 0.0/sec 0.000/sec 0.0008/sec total: 3 2022-06-20T14:50:19.812Z|00330|coverage|INFO|vconn_received 0.2/sec 0.033/sec 0.5300/sec total: 1908 2022-06-20T14:50:19.812Z|00331|coverage|INFO|vconn_sent 0.2/sec 0.050/sec 9.2656/sec total: 33758 2022-06-20T14:50:19.812Z|00332|coverage|INFO|netlink_received 0.0/sec 0.000/sec 0.8431/sec total: 3038 2022-06-20T14:50:19.812Z|00333|coverage|INFO|netlink_recv_jumbo 0.0/sec 0.000/sec 0.2806/sec total: 1011 2022-06-20T14:50:19.812Z|00334|coverage|INFO|netlink_sent 0.0/sec 0.000/sec 0.8431/sec total: 3038 2022-06-20T14:50:19.812Z|00335|coverage|INFO|cmap_expand 0.0/sec 0.000/sec 0.0008/sec total: 3 2022-06-20T14:50:19.812Z|00336|coverage|INFO|101 events never hit 2022-06-20T14:50:19.812Z|00337|poll_loop|INFO|Dropped 136 log messages in last 160 seconds (most recently, 157 seconds ago) due to excessive rate 2022-06-20T14:50:19.813Z|00338|poll_loop|INFO|wakeup due to [POLLIN][POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (99% CPU usage) 2022-06-20T14:50:19.814Z|00339|poll_loop|INFO|wakeup due to [POLLIN] on fd 19 (10.0.154.173:52318<->10.0.157.93:9642) at lib/stream-ssl.c:836 (99% CPU usage) 2022-06-20T14:50:19.814Z|00340|memory|INFO|peak resident set size grew 167% in last 164.9 seconds, from 597040 kB to 1594384 kB 2022-06-20T14:50:19.815Z|00341|memory|INFO|idl-cells:6542911 if_status_mgr_ifaces_state_usage-KB:1 if_status_mgr_ifaces_usage-KB:1 lflow-cache-entries-cache-expr:4075 lflow-cache-entries-cache-matches:9494 lflow-cache-size-KB:10096 local_datapath_usage-KB:5 ofctrl_desired_flow_usage-KB:5646 ofctrl_installed_flow_usage-KB:4427 ofctrl_rconn_packet_counter-KB:1115 ofctrl_sb_flow_ref_usage-KB:2357 oflow_update_usage-KB:1 2022-06-20T14:50:19.929Z|00342|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (99% CPU usage) 2022-06-20T14:50:19.931Z|00343|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (99% CPU usage) 2022-06-20T14:50:19.933Z|00344|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (99% CPU usage) 2022-06-20T14:50:19.934Z|00345|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (99% CPU usage) 2022-06-20T14:50:19.936Z|00346|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (99% CPU usage) 2022-06-20T14:50:19.937Z|00347|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (99% CPU usage) 2022-06-20T14:50:19.938Z|00348|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (99% CPU usage) 2022-06-20T14:50:19.940Z|00349|poll_loop|INFO|wakeup due to [POLLOUT] on fd 21 (<->/var/run/openvswitch/br-int.mgmt) at lib/stream-fd.c:153 (99% CPU usage) 2022-06-20T14:50:49.562Z|00350|lflow_cache|INFO|Detected cache inactivity (last active 30005 ms ago): trimming cache 2022-06-20T15:04:20.185Z|00351|ovsdb_cs|INFO|ssl:10.0.157.93:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T15:04:20.186Z|00352|reconnect|INFO|ssl:10.0.157.93:9642: connection attempt timed out 2022-06-20T15:04:20.187Z|00353|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T15:04:20.188Z|00354|reconnect|INFO|ssl:10.0.188.134:9642: connecting... 2022-06-20T15:04:21.189Z|00355|reconnect|INFO|ssl:10.0.188.134:9642: connection attempt timed out 2022-06-20T15:04:21.191Z|00356|reconnect|INFO|ssl:10.0.196.167:9642: connecting... 2022-06-20T15:04:21.423Z|00357|reconnect|INFO|ssl:10.0.196.167:9642: connected 2022-06-20T15:14:35.615Z|00358|ovsdb_cs|INFO|ssl:10.0.196.167:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T15:14:35.616Z|00359|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T15:14:35.616Z|00360|reconnect|INFO|ssl:10.0.196.167:9642: connection attempt timed out 2022-06-20T15:14:35.618Z|00361|reconnect|INFO|ssl:10.0.157.93:9642: connecting... 2022-06-20T15:14:35.631Z|00362|reconnect|INFO|ssl:10.0.157.93:9642: connected 2022-06-20T15:20:36.444Z|00363|ovsdb_cs|INFO|ssl:10.0.157.93:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T15:20:36.446Z|00364|reconnect|INFO|ssl:10.0.157.93:9642: connection attempt timed out 2022-06-20T15:20:36.447Z|00365|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T15:20:36.447Z|00366|reconnect|INFO|ssl:10.0.188.134:9642: connecting... 2022-06-20T15:20:36.680Z|00367|reconnect|INFO|ssl:10.0.188.134:9642: connected 2022-06-20T15:41:38.452Z|00368|ovsdb_cs|INFO|ssl:10.0.188.134:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T15:41:38.453Z|00369|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T15:41:38.454Z|00370|reconnect|INFO|ssl:10.0.188.134:9642: connection attempt timed out 2022-06-20T15:41:38.455Z|00371|reconnect|INFO|ssl:10.0.196.167:9642: connecting... 2022-06-20T15:41:39.456Z|00372|reconnect|INFO|ssl:10.0.196.167:9642: connection attempt timed out 2022-06-20T15:41:39.458Z|00373|reconnect|INFO|ssl:10.0.157.93:9642: connecting... 2022-06-20T15:41:40.460Z|00374|reconnect|INFO|ssl:10.0.157.93:9642: connection attempt timed out 2022-06-20T15:41:40.461Z|00375|reconnect|INFO|ssl:10.0.188.134:9642: connecting... 2022-06-20T15:41:40.892Z|00376|reconnect|INFO|ssl:10.0.188.134:9642: connected 2022-06-20T15:41:40.897Z|00377|ovsdb_cs|INFO|ssl:10.0.188.134:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T15:41:40.898Z|00378|reconnect|INFO|ssl:10.0.188.134:9642: connection attempt timed out 2022-06-20T15:41:41.900Z|00379|reconnect|INFO|ssl:10.0.196.167:9642: connecting... 2022-06-20T15:41:41.905Z|00380|reconnect|INFO|ssl:10.0.196.167:9642: connected 2022-06-20T15:54:45.867Z|00381|ovsdb_cs|INFO|ssl:10.0.196.167:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T15:54:45.868Z|00382|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T15:54:45.869Z|00383|reconnect|INFO|ssl:10.0.196.167:9642: connection attempt timed out 2022-06-20T15:54:45.870Z|00384|reconnect|INFO|ssl:10.0.157.93:9642: connecting... 2022-06-20T15:54:46.305Z|00385|reconnect|INFO|ssl:10.0.157.93:9642: connected 2022-06-20T15:59:36.475Z|00386|ovsdb_cs|INFO|ssl:10.0.157.93:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T15:59:36.476Z|00387|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T15:59:36.477Z|00388|reconnect|INFO|ssl:10.0.157.93:9642: connection attempt timed out 2022-06-20T15:59:36.479Z|00389|reconnect|INFO|ssl:10.0.188.134:9642: connecting... 2022-06-20T15:59:37.480Z|00390|reconnect|INFO|ssl:10.0.188.134:9642: connection attempt timed out 2022-06-20T15:59:37.482Z|00391|reconnect|INFO|ssl:10.0.196.167:9642: connecting... 2022-06-20T15:59:37.499Z|00392|reconnect|INFO|ssl:10.0.196.167:9642: connected 2022-06-20T16:03:29.038Z|00393|ovsdb_cs|INFO|ssl:10.0.196.167:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T16:03:29.039Z|00394|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T16:03:29.040Z|00395|reconnect|INFO|ssl:10.0.196.167:9642: connection attempt timed out 2022-06-20T16:03:29.041Z|00396|reconnect|INFO|ssl:10.0.157.93:9642: connecting... 2022-06-20T16:03:29.048Z|00397|reconnect|INFO|ssl:10.0.157.93:9642: connected 2022-06-20T16:03:29.579Z|00398|inc_proc_eng|INFO|node: logical_flow_output, recompute (forced) took 519ms 2022-06-20T16:07:29.287Z|00399|ovsdb_cs|INFO|ssl:10.0.157.93:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T16:07:29.288Z|00400|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T16:07:29.288Z|00401|reconnect|INFO|ssl:10.0.157.93:9642: connection attempt timed out 2022-06-20T16:07:29.290Z|00402|reconnect|INFO|ssl:10.0.188.134:9642: connecting... 2022-06-20T16:07:30.291Z|00403|reconnect|INFO|ssl:10.0.188.134:9642: connection attempt timed out 2022-06-20T16:07:30.293Z|00404|reconnect|INFO|ssl:10.0.196.167:9642: connecting... 2022-06-20T16:07:30.313Z|00405|reconnect|INFO|ssl:10.0.196.167:9642: connected 2022-06-20T16:12:25.514Z|00406|ovsdb_cs|INFO|ssl:10.0.196.167:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T16:12:25.515Z|00407|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T16:12:25.515Z|00408|reconnect|INFO|ssl:10.0.196.167:9642: connection attempt timed out 2022-06-20T16:12:25.517Z|00409|reconnect|INFO|ssl:10.0.157.93:9642: connecting... 2022-06-20T16:12:25.728Z|00410|reconnect|INFO|ssl:10.0.157.93:9642: connected 2022-06-20T16:25:58.506Z|00411|ovsdb_cs|INFO|ssl:10.0.157.93:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T16:25:58.508Z|00412|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T16:25:58.508Z|00413|reconnect|INFO|ssl:10.0.157.93:9642: connection attempt timed out 2022-06-20T16:25:58.509Z|00414|reconnect|INFO|ssl:10.0.188.134:9642: connecting... 2022-06-20T16:25:58.933Z|00415|reconnect|INFO|ssl:10.0.188.134:9642: connected 2022-06-20T16:38:40.535Z|00416|ovsdb_cs|INFO|ssl:10.0.188.134:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T16:38:40.536Z|00417|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T16:38:40.536Z|00418|reconnect|INFO|ssl:10.0.188.134:9642: connection attempt timed out 2022-06-20T16:38:40.538Z|00419|reconnect|INFO|ssl:10.0.196.167:9642: connecting... 2022-06-20T16:38:41.539Z|00420|reconnect|INFO|ssl:10.0.196.167:9642: connection attempt timed out 2022-06-20T16:38:41.540Z|00421|reconnect|INFO|ssl:10.0.157.93:9642: connecting... 2022-06-20T16:38:41.547Z|00422|reconnect|INFO|ssl:10.0.157.93:9642: connected 2022-06-20T16:39:49.688Z|00423|ovsdb_cs|INFO|ssl:10.0.157.93:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T16:39:49.689Z|00424|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T16:39:49.689Z|00425|reconnect|INFO|ssl:10.0.157.93:9642: connection attempt timed out 2022-06-20T16:39:49.691Z|00426|reconnect|INFO|ssl:10.0.188.134:9642: connecting... 2022-06-20T16:39:49.705Z|00427|reconnect|INFO|ssl:10.0.188.134:9642: connected 2022-06-20T16:43:07.584Z|00428|ovsdb_cs|INFO|ssl:10.0.188.134:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T16:43:07.585Z|00429|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T16:43:07.585Z|00430|reconnect|INFO|ssl:10.0.188.134:9642: connection attempt timed out 2022-06-20T16:43:07.587Z|00431|reconnect|INFO|ssl:10.0.196.167:9642: connecting... 2022-06-20T16:43:07.806Z|00432|reconnect|INFO|ssl:10.0.196.167:9642: connected 2022-06-20T16:44:46.892Z|00433|ovsdb_cs|INFO|ssl:10.0.196.167:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T16:44:46.893Z|00434|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T16:44:46.893Z|00435|reconnect|INFO|ssl:10.0.196.167:9642: connection attempt timed out 2022-06-20T16:44:46.895Z|00436|reconnect|INFO|ssl:10.0.157.93:9642: connecting... 2022-06-20T16:44:47.896Z|00437|reconnect|INFO|ssl:10.0.157.93:9642: connection attempt timed out 2022-06-20T16:44:47.898Z|00438|reconnect|INFO|ssl:10.0.188.134:9642: connecting... 2022-06-20T16:44:48.110Z|00439|reconnect|INFO|ssl:10.0.188.134:9642: connected 2022-06-20T16:59:42.331Z|00440|ovsdb_cs|INFO|ssl:10.0.188.134:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T16:59:42.332Z|00441|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T16:59:42.332Z|00442|reconnect|INFO|ssl:10.0.188.134:9642: connection attempt timed out 2022-06-20T16:59:42.334Z|00443|reconnect|INFO|ssl:10.0.196.167:9642: connecting... 2022-06-20T16:59:43.335Z|00444|reconnect|INFO|ssl:10.0.196.167:9642: connection attempt timed out 2022-06-20T16:59:43.337Z|00445|reconnect|INFO|ssl:10.0.157.93:9642: connecting... 2022-06-20T16:59:43.342Z|00446|reconnect|INFO|ssl:10.0.157.93:9642: connected 2022-06-20T17:08:33.718Z|00447|ovsdb_cs|INFO|ssl:10.0.157.93:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T17:08:33.720Z|00448|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T17:08:33.720Z|00449|reconnect|INFO|ssl:10.0.157.93:9642: connection attempt timed out 2022-06-20T17:08:33.721Z|00450|reconnect|INFO|ssl:10.0.188.134:9642: connecting... 2022-06-20T17:08:34.142Z|00451|reconnect|INFO|ssl:10.0.188.134:9642: connected 2022-06-20T17:19:41.582Z|00452|ovsdb_cs|INFO|ssl:10.0.188.134:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T17:19:41.583Z|00453|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T17:19:41.583Z|00454|reconnect|INFO|ssl:10.0.188.134:9642: connection attempt timed out 2022-06-20T17:19:41.585Z|00455|reconnect|INFO|ssl:10.0.196.167:9642: connecting... 2022-06-20T17:19:42.586Z|00456|reconnect|INFO|ssl:10.0.196.167:9642: connection attempt timed out 2022-06-20T17:19:42.588Z|00457|reconnect|INFO|ssl:10.0.157.93:9642: connecting... 2022-06-20T17:19:42.612Z|00458|reconnect|INFO|ssl:10.0.157.93:9642: connected 2022-06-20T17:20:47.422Z|00459|ovsdb_cs|INFO|ssl:10.0.157.93:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T17:20:47.424Z|00460|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T17:20:47.424Z|00461|reconnect|INFO|ssl:10.0.157.93:9642: connection attempt timed out 2022-06-20T17:20:47.425Z|00462|reconnect|INFO|ssl:10.0.188.134:9642: connecting... 2022-06-20T17:20:47.442Z|00463|reconnect|INFO|ssl:10.0.188.134:9642: connected 2022-06-20T17:29:59.307Z|00464|ovsdb_cs|INFO|ssl:10.0.188.134:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T17:29:59.308Z|00465|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T17:29:59.308Z|00466|reconnect|INFO|ssl:10.0.188.134:9642: connection attempt timed out 2022-06-20T17:29:59.310Z|00467|reconnect|INFO|ssl:10.0.196.167:9642: connecting... 2022-06-20T17:29:59.750Z|00468|reconnect|INFO|ssl:10.0.196.167:9642: connected 2022-06-20T17:52:06.824Z|00469|ovsdb_cs|INFO|ssl:10.0.196.167:9642: clustered database server is disconnected from cluster; trying another server 2022-06-20T17:52:06.825Z|00470|main|INFO|OVNSB commit failed, force recompute next time. 2022-06-20T17:52:06.825Z|00471|reconnect|INFO|ssl:10.0.196.167:9642: connection attempt timed out 2022-06-20T17:52:06.827Z|00472|reconnect|INFO|ssl:10.0.157.93:9642: connecting... 2022-06-20T17:52:07.047Z|00473|reconnect|INFO|ssl:10.0.157.93:9642: connected it never recovers...
SBDB on high CPU: [surya@hidden-temple scripts]$ oc adm top pod -n openshift-ovn-kubernetes --containers POD NAME CPU(cores) MEMORY(bytes) ovnkube-master-cqtmn POD 0m 0Mi ovnkube-master-cqtmn kube-rbac-proxy 0m 18Mi ovnkube-master-cqtmn nbdb 2m 814Mi ovnkube-master-cqtmn northd 0m 3384Mi ovnkube-master-cqtmn ovn-dbchecker 0m 32Mi ovnkube-master-cqtmn ovnkube-master 405m 1361Mi ovnkube-master-cqtmn sbdb 192m 3171Mi ovnkube-master-dbtxl POD 0m 0Mi ovnkube-master-dbtxl kube-rbac-proxy 0m 23Mi ovnkube-master-dbtxl nbdb 1m 809Mi ovnkube-master-dbtxl northd 0m 2347Mi ovnkube-master-dbtxl ovn-dbchecker 0m 30Mi ovnkube-master-dbtxl ovnkube-master 260m 1345Mi ovnkube-master-dbtxl sbdb 437m 3095Mi ovnkube-master-qzk8b POD 0m 0Mi ovnkube-master-qzk8b kube-rbac-proxy 0m 23Mi ovnkube-master-qzk8b nbdb 1m 1170Mi ovnkube-master-qzk8b northd 0m 2918Mi ovnkube-master-qzk8b ovn-dbchecker 1m 31Mi ovnkube-master-qzk8b ovnkube-master 213m 2491Mi ovnkube-master-qzk8b sbdb 309m 3226Mi after a while: [surya@hidden-temple scripts]$ oc adm top pod -n openshift-ovn-kubernetes --containers POD NAME CPU(cores) MEMORY(bytes) ovnkube-master-cqtmn POD 0m 0Mi ovnkube-master-cqtmn kube-rbac-proxy 0m 19Mi ovnkube-master-cqtmn nbdb 1m 814Mi ovnkube-master-cqtmn northd 0m 3384Mi ovnkube-master-cqtmn ovn-dbchecker 0m 31Mi ovnkube-master-cqtmn ovnkube-master 0m 1154Mi ovnkube-master-cqtmn sbdb 889m 3173Mi ovnkube-master-dbtxl POD 0m 0Mi ovnkube-master-dbtxl kube-rbac-proxy 0m 23Mi ovnkube-master-dbtxl nbdb 1m 809Mi ovnkube-master-dbtxl northd 0m 2347Mi ovnkube-master-dbtxl ovn-dbchecker 0m 30Mi ovnkube-master-dbtxl ovnkube-master 1m 1219Mi ovnkube-master-dbtxl sbdb 433m 3002Mi ovnkube-master-qzk8b POD 0m 0Mi ovnkube-master-qzk8b kube-rbac-proxy 0m 22Mi ovnkube-master-qzk8b nbdb 2m 1170Mi ovnkube-master-qzk8b northd 0m 2918Mi ovnkube-master-qzk8b ovn-dbchecker 0m 32Mi ovnkube-master-qzk8b ovnkube-master 3m 2497Mi ovnkube-master-qzk8b sbdb 530m 3226Mi SBDB at that time: 2022-06-20T14:48:37.188Z|00907|coverage|INFO|Skipping details of duplicate event coverage for hash=884724c9 2022-06-20T14:48:38.312Z|00908|timeval|WARN|Unreasonably long 1122ms poll interval (1026ms user, 81ms system) 2022-06-20T14:48:38.314Z|00909|timeval|WARN|faults: 11307 minor, 0 major 2022-06-20T14:48:38.316Z|00910|timeval|WARN|disk: 0 reads, 16 writes 2022-06-20T14:48:38.318Z|00911|timeval|WARN|context switches: 0 voluntary, 21 involuntary 2022-06-20T14:48:38.442Z|00912|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:48:38.677Z|00913|poll_loop|INFO|Dropped 426 log messages in last 21 seconds (most recently, 21 seconds ago) due to excessive rate 2022-06-20T14:48:38.677Z|00914|poll_loop|INFO|wakeup due to 1-ms timeout at ../lib/reconnect.c:677 (91% CPU usage) 2022-06-20T14:48:38.678Z|00915|poll_loop|INFO|wakeup due to 1-ms timeout at ../lib/reconnect.c:677 (91% CPU usage) 2022-06-20T14:48:38.679Z|00916|poll_loop|INFO|wakeup due to 1-ms timeout at ../lib/reconnect.c:677 (91% CPU usage) 2022-06-20T14:48:41.134Z|00917|poll_loop|INFO|Dropped 1831 log messages in last 3 seconds (most recently, 0 seconds ago) due to excessive rate 2022-06-20T14:48:41.135Z|00918|poll_loop|INFO|wakeup due to 1-ms timeout at ../lib/reconnect.c:677 (91% CPU usage) 2022-06-20T14:48:48.421Z|00919|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:48:58.429Z|00920|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:49:08.419Z|00921|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:49:18.432Z|00922|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:49:28.411Z|00923|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:49:38.426Z|00924|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:49:48.434Z|00925|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:49:53.681Z|00926|poll_loop|INFO|Dropped 367 log messages in last 72 seconds (most recently, 72 seconds ago) due to excessive rate 2022-06-20T14:49:53.681Z|00927|poll_loop|INFO|wakeup due to 0-ms timeout at ../lib/stream-ssl.c:838 (59% CPU usage) 2022-06-20T14:49:53.684Z|00928|poll_loop|INFO|wakeup due to 0-ms timeout at ../lib/stream-ssl.c:838 (59% CPU usage) 2022-06-20T14:49:53.687Z|00929|poll_loop|INFO|wakeup due to 0-ms timeout at ../lib/stream-ssl.c:838 (59% CPU usage) 2022-06-20T14:49:53.691Z|00930|poll_loop|INFO|wakeup due to 0-ms timeout at ../lib/stream-ssl.c:838 (59% CPU usage) 2022-06-20T14:49:53.694Z|00931|poll_loop|INFO|wakeup due to 0-ms timeout at ../lib/stream-ssl.c:838 (59% CPU usage) 2022-06-20T14:49:53.698Z|00932|poll_loop|INFO|wakeup due to 0-ms timeout at ../lib/stream-ssl.c:838 (59% CPU usage) 2022-06-20T14:49:53.701Z|00933|poll_loop|INFO|wakeup due to 0-ms timeout at ../lib/stream-ssl.c:838 (59% CPU usage) 2022-06-20T14:49:53.704Z|00934|poll_loop|INFO|wakeup due to 0-ms timeout at ../lib/stream-ssl.c:838 (59% CPU usage) 2022-06-20T14:49:53.708Z|00935|poll_loop|INFO|wakeup due to 0-ms timeout at ../lib/stream-ssl.c:838 (59% CPU usage) 2022-06-20T14:49:53.711Z|00936|poll_loop|INFO|wakeup due to 0-ms timeout at ../lib/stream-ssl.c:838 (59% CPU usage) 2022-06-20T14:49:55.637Z|00937|timeval|WARN|Unreasonably long 1383ms poll interval (1272ms user, 99ms system) 2022-06-20T14:49:55.637Z|00938|timeval|WARN|faults: 5102 minor, 0 major 2022-06-20T14:49:55.637Z|00939|timeval|WARN|disk: 0 reads, 239440 writes 2022-06-20T14:49:55.637Z|00940|timeval|WARN|context switches: 0 voluntary, 15 involuntary 2022-06-20T14:49:55.637Z|00941|coverage|INFO|Dropped 1 log messages in last 77 seconds (most recently, 77 seconds ago) due to excessive rate 2022-06-20T14:49:55.637Z|00942|coverage|INFO|Skipping details of duplicate event coverage for hash=884724c9 2022-06-20T14:50:01.631Z|00943|timeval|WARN|Unreasonably long 5866ms poll interval (5460ms user, 352ms system) 2022-06-20T14:50:01.632Z|00944|timeval|WARN|faults: 211662 minor, 0 major 2022-06-20T14:50:01.633Z|00945|timeval|WARN|context switches: 0 voluntary, 71 involuntary 2022-06-20T14:50:01.635Z|00946|poll_loop|INFO|Dropped 270 log messages in last 8 seconds (most recently, 6 seconds ago) due to excessive rate 2022-06-20T14:50:01.636Z|00947|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (98% CPU usage) 2022-06-20T14:50:01.640Z|00948|jsonrpc|WARN|unix#1972: send error: Broken pipe 2022-06-20T14:50:12.067Z|00949|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T14:50:12.067Z|00950|jsonrpc|WARN|ssl:10.0.157.93:50678: receive error: Protocol error 2022-06-20T14:50:12.068Z|00951|timeval|WARN|Unreasonably long 10434ms poll interval (8636ms user, 1702ms system) 2022-06-20T14:50:12.068Z|00952|timeval|WARN|faults: 62686 minor, 0 major 2022-06-20T14:50:12.068Z|00953|timeval|WARN|disk: 0 reads, 8 writes 2022-06-20T14:50:12.068Z|00954|timeval|WARN|context switches: 0 voluntary, 112 involuntary 2022-06-20T14:50:12.068Z|00955|poll_loop|INFO|Dropped 1 log messages in last 11 seconds (most recently, 11 seconds ago) due to excessive rate 2022-06-20T14:50:12.068Z|00956|poll_loop|INFO|wakeup due to [POLLOUT] on fd 77 (10.0.157.93:9642<->10.0.200.65:42812) at ../lib/stream-ssl.c:802 (99% CPU usage) 2022-06-20T14:50:12.068Z|00957|poll_loop|INFO|wakeup due to [POLLOUT] on fd 70 (10.0.157.93:9642<->10.0.138.94:47982) at ../lib/stream-ssl.c:802 (99% CPU usage) 2022-06-20T14:50:12.069Z|00958|memory|INFO|peak resident set size grew 219% in last 171.1 seconds, from 2288332 kB to 7290332 kB 2022-06-20T14:50:12.069Z|00959|memory|INFO|atoms:9653390 backlog:377 cells:7318091 monitors:2 raft-connections:4 raft-log:4285 sessions:46 triggers:7 txn-history:100 txn-history-atoms:4502043 2022-06-20T14:50:12.069Z|00960|jsonrpc|WARN|unix#1974: send error: Broken pipe 2022-06-20T14:50:12.162Z|00961|reconnect|WARN|ssl:10.0.157.93:50678: connection dropped (Protocol error) 2022-06-20T14:50:17.681Z|00962|poll_loop|INFO|Dropped 2227 log messages in last 5 seconds (most recently, 0 seconds ago) due to excessive rate 2022-06-20T14:50:17.681Z|00963|poll_loop|INFO|wakeup due to 1-ms timeout at ../lib/reconnect.c:677 (91% CPU usage) 2022-06-20T14:50:18.417Z|00964|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:50:28.431Z|00965|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:50:45.403Z|00966|timeval|WARN|Unreasonably long 13674ms poll interval (13314ms user, 213ms system) 2022-06-20T14:50:45.405Z|00967|timeval|WARN|faults: 63165 minor, 0 major 2022-06-20T14:50:45.406Z|00968|timeval|WARN|disk: 0 reads, 8 writes 2022-06-20T14:50:45.407Z|00969|timeval|WARN|context switches: 0 voluntary, 157 involuntary 2022-06-20T14:50:45.408Z|00970|coverage|INFO|Dropped 2 log messages in last 44 seconds (most recently, 33 seconds ago) due to excessive rate 2022-06-20T14:50:45.410Z|00971|coverage|INFO|Skipping details of duplicate event coverage for hash=884724c9 2022-06-20T14:50:45.411Z|00972|poll_loop|INFO|Dropped 331 log messages in last 28 seconds (most recently, 27 seconds ago) due to excessive rate 2022-06-20T14:50:45.415Z|00973|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (90% CPU usage) 2022-06-20T14:50:45.417Z|00974|poll_loop|INFO|wakeup due to [POLLIN] on fd 86 (10.0.157.93:9642<->10.0.215.207:46158) at ../lib/stream-ssl.c:836 (90% CPU usage) 2022-06-20T14:50:45.420Z|00975|poll_loop|INFO|wakeup due to [POLLIN] on fd 65 (10.0.157.93:9642<->10.0.154.173:52318) at ../lib/stream-ssl.c:836 (90% CPU usage) 2022-06-20T14:50:45.424Z|00976|poll_loop|INFO|wakeup due to [POLLIN] on fd 41 (10.0.157.93:9642<->10.0.130.161:33652) at ../lib/stream-ssl.c:836 (90% CPU usage) 2022-06-20T14:50:45.445Z|00977|jsonrpc|WARN|unix#1980: send error: Broken pipe 2022-06-20T14:50:45.453Z|00978|jsonrpc|WARN|unix#1981: send error: Broken pipe 2022-06-20T14:50:45.547Z|00979|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T14:50:45.548Z|00980|jsonrpc|WARN|ssl:10.0.129.39:41246: receive error: Protocol error 2022-06-20T14:50:45.790Z|00981|reconnect|WARN|ssl:10.0.129.39:41246: connection dropped (Protocol error) 2022-06-20T14:50:45.825Z|00982|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T14:50:45.826Z|00983|jsonrpc|WARN|ssl:10.0.196.167:58764: receive error: Protocol error 2022-06-20T14:50:45.868Z|00984|reconnect|WARN|ssl:10.0.196.167:58764: connection dropped (Protocol error) 2022-06-20T14:50:45.870Z|00985|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T14:50:45.870Z|00986|jsonrpc|WARN|ssl:10.0.129.39:41254: receive error: Protocol error 2022-06-20T14:50:45.883Z|00987|reconnect|WARN|ssl:10.0.129.39:41254: connection dropped (Protocol error) 2022-06-20T14:50:45.884Z|00988|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T14:50:45.890Z|00989|reconnect|WARN|ssl:10.0.157.93:52180: connection dropped (Protocol error) 2022-06-20T14:50:47.681Z|00990|poll_loop|INFO|Dropped 1415 log messages in last 2 seconds (most recently, 0 seconds ago) due to excessive rate 2022-06-20T14:50:47.681Z|00991|poll_loop|INFO|wakeup due to 2-ms timeout at ../lib/reconnect.c:677 (90% CPU usage) 2022-06-20T14:50:48.433Z|00992|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:50:58.420Z|00993|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:50:59.920Z|00994|raft|INFO|received leadership transfer from fdb3 in term 6 2022-06-20T14:50:59.920Z|00995|raft|INFO|term 7: starting election 2022-06-20T14:50:59.924Z|00996|raft|INFO|term 7: elected leader by 2+ of 3 servers 2022-06-20T14:51:00.038Z|00997|raft|INFO|current entry eid f3f45d62-a305-4dcc-b8cd-990966b5d566 does not match prerequisite 7dcb650b-e4c4-45d5-90bb-55dcdf89ed68 in execute_command_request 2022-06-20T14:51:00.040Z|00998|raft|INFO|current entry eid f3f45d62-a305-4dcc-b8cd-990966b5d566 does not match prerequisite 7dcb650b-e4c4-45d5-90bb-55dcdf89ed68 in execute_command_request 2022-06-20T14:51:00.041Z|00999|raft|INFO|current entry eid f3f45d62-a305-4dcc-b8cd-990966b5d566 does not match prerequisite 7dcb650b-e4c4-45d5-90bb-55dcdf89ed68 in execute_command_request 2022-06-20T14:51:00.046Z|01000|raft|INFO|current entry eid 705f46fb-cab1-432f-b2d3-1119564b2e54 does not match prerequisite f3f45d62-a305-4dcc-b8cd-990966b5d566 in execute_command_request 2022-06-20T14:51:00.046Z|01001|raft|INFO|current entry eid 705f46fb-cab1-432f-b2d3-1119564b2e54 does not match prerequisite f3f45d62-a305-4dcc-b8cd-990966b5d566 in execute_command_request 2022-06-20T14:51:24.759Z|01002|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T14:51:24.761Z|01003|jsonrpc|WARN|Dropped 1 log messages in last 38 seconds (most recently, 38 seconds ago) due to excessive rate 2022-06-20T14:51:24.762Z|01004|jsonrpc|WARN|ssl:10.0.157.93:52962: send error: Broken pipe 2022-06-20T14:51:24.896Z|01005|raft|INFO|Dropped 38 log messages in last 25 seconds (most recently, 19 seconds ago) due to excessive rate 2022-06-20T14:51:24.898Z|01006|raft|INFO|current entry eid 683a6053-3b1a-48cf-9967-1b9523c5a28b does not match prerequisite 3ecfa0ec-f33a-4cfa-b481-cbcbf43ea437 in execute_command_request 2022-06-20T14:51:24.938Z|01007|raft|INFO|current entry eid 683a6053-3b1a-48cf-9967-1b9523c5a28b does not match prerequisite 3ecfa0ec-f33a-4cfa-b481-cbcbf43ea437 in execute_command_request 2022-06-20T14:51:24.991Z|01008|raft|WARN|ignoring vote request received as leader 2022-06-20T14:51:25.024Z|01009|timeval|WARN|Unreasonably long 16667ms poll interval (16059ms user, 322ms system) 2022-06-20T14:51:25.026Z|01010|timeval|WARN|faults: 81750 minor, 0 major 2022-06-20T14:51:25.027Z|01011|timeval|WARN|disk: 0 reads, 8 writes 2022-06-20T14:51:25.028Z|01012|timeval|WARN|context switches: 0 voluntary, 386 involuntary 2022-06-20T14:51:25.030Z|01013|poll_loop|INFO|Dropped 575 log messages in last 38 seconds (most recently, 37 seconds ago) due to excessive rate 2022-06-20T14:51:25.033Z|01014|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (89% CPU usage) 2022-06-20T14:51:25.035Z|01015|poll_loop|INFO|wakeup due to [POLLIN] on fd 66 (10.0.157.93:9642<->10.0.131.67:39148) at ../lib/stream-ssl.c:836 (89% CPU usage) 2022-06-20T14:51:25.038Z|01016|poll_loop|INFO|wakeup due to [POLLIN] on fd 55 (10.0.157.93:9642<->10.0.191.87:59920) at ../lib/stream-ssl.c:836 (89% CPU usage) 2022-06-20T14:51:25.041Z|01017|poll_loop|INFO|wakeup due to [POLLIN] on fd 63 (10.0.157.93:9642<->10.0.140.41:44404) at ../lib/stream-ssl.c:836 (89% CPU usage) 2022-06-20T14:51:25.044Z|01018|poll_loop|INFO|wakeup due to [POLLIN] on fd 76 (10.0.157.93:9642<->10.0.186.219:59278) at ../lib/stream-ssl.c:836 (89% CPU usage) 2022-06-20T14:51:25.046Z|01019|poll_loop|INFO|wakeup due to [POLLIN] on fd 39 (10.0.157.93:9642<->10.0.196.167:59218) at ../lib/stream-ssl.c:836 (89% CPU usage) 2022-06-20T14:51:25.054Z|01020|jsonrpc|WARN|unix#1993: send error: Broken pipe 2022-06-20T14:51:25.061Z|01021|jsonrpc|WARN|unix#1994: send error: Broken pipe 2022-06-20T14:51:25.102Z|01022|reconnect|WARN|ssl:10.0.157.93:52962: connection dropped (Broken pipe) 2022-06-20T14:51:25.144Z|01023|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T14:51:25.145Z|01024|jsonrpc|WARN|ssl:10.0.196.167:59704: receive error: Protocol error 2022-06-20T14:51:25.148Z|01025|raft|INFO|rejected append_reply (not leader) 2022-06-20T14:51:25.152Z|01026|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.158Z|01027|stream_ssl|WARN|SSL_write: system error (Connection reset by peer) 2022-06-20T14:51:25.174Z|01028|reconnect|WARN|ssl:10.0.196.167:59704: connection dropped (Protocol error) 2022-06-20T14:51:25.188Z|01029|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.190Z|01030|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.192Z|01031|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.194Z|01032|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.195Z|01033|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.197Z|01034|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.198Z|01035|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.200Z|01036|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.202Z|01037|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.203Z|01038|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.204Z|01039|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.206Z|01040|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.207Z|01041|raft|INFO|rejecting term 7 < current term 8 received in append_reply message from server fdb3 2022-06-20T14:51:25.214Z|01042|reconnect|WARN|ssl:10.0.196.167:59218: connection dropped (Connection reset by peer) 2022-06-20T14:51:29.680Z|01043|poll_loop|INFO|Dropped 3802 log messages in last 4 seconds (most recently, 0 seconds ago) due to excessive rate 2022-06-20T14:51:29.680Z|01044|poll_loop|INFO|wakeup due to [POLLIN] on fd 37 (10.0.157.93:9642<->10.0.188.134:58022) at ../lib/stream-ssl.c:836 (52% CPU usage) 2022-06-20T14:51:38.887Z|01045|raft|WARN|ignoring vote request received after only 13739 ms (minimum election time is 16000 ms) 2022-06-20T14:51:40.824Z|01046|raft|WARN|ignoring vote request received after only 15676 ms (minimum election time is 16000 ms) 2022-06-20T14:51:40.830Z|01047|raft|INFO|server fdb3 is leader for term 8 2022-06-20T14:51:43.035Z|01048|poll_loop|INFO|Dropped 1218 log messages in last 14 seconds (most recently, 12 seconds ago) due to excessive rate 2022-06-20T14:51:43.036Z|01049|poll_loop|INFO|wakeup due to 1-ms timeout at ../lib/reconnect.c:677 (51% CPU usage) 2022-06-20T14:51:43.037Z|01050|poll_loop|INFO|wakeup due to 1-ms timeout at ../lib/reconnect.c:677 (51% CPU usage) 2022-06-20T14:51:47.681Z|01051|poll_loop|INFO|Dropped 3802 log messages in last 4 seconds (most recently, 0 seconds ago) due to excessive rate 2022-06-20T14:51:47.682Z|01052|poll_loop|INFO|wakeup due to [POLLIN] on fd 106 (10.0.157.93:9642<->10.0.196.167:34850) at ../lib/stream-ssl.c:836 (51% CPU usage) 2022-06-20T14:51:48.438Z|01053|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:51:53.681Z|01054|poll_loop|INFO|Dropped 4941 log messages in last 6 seconds (most recently, 0 seconds ago) due to excessive rate 2022-06-20T14:51:53.681Z|01055|poll_loop|INFO|wakeup due to [POLLIN] on fd 106 (10.0.157.93:9642<->10.0.188.134:33412) at ../lib/stream-ssl.c:836 (54% CPU usage) 2022-06-20T14:51:55.234Z|01056|raft|WARN|ignoring vote request received after only 14403 ms (minimum election time is 16000 ms) 2022-06-20T14:51:57.537Z|01057|raft|INFO|server fdb3 is leader for term 10 2022-06-20T14:51:58.418Z|01058|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:51:59.680Z|01059|poll_loop|INFO|Dropped 4727 log messages in last 6 seconds (most recently, 0 seconds ago) due to excessive rate 2022-06-20T14:51:59.680Z|01060|poll_loop|INFO|wakeup due to 1-ms timeout at ../lib/reconnect.c:677 (55% CPU usage) 2022-06-20T14:52:08.430Z|01061|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:52:18.424Z|01062|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:52:38.636Z|01063|ovsdb|INFO|OVN_Southbound: Database compaction took 16975ms 2022-06-20T14:52:38.640Z|01064|timeval|WARN|Unreasonably long 16980ms poll interval (15358ms user, 275ms system) 2022-06-20T14:52:38.642Z|01065|timeval|WARN|faults: 537 minor, 0 major 2022-06-20T14:52:38.644Z|01066|timeval|WARN|disk: 0 reads, 547992 writes 2022-06-20T14:52:38.645Z|01067|timeval|WARN|context switches: 3019 voluntary, 186 involuntary 2022-06-20T14:52:38.647Z|01068|coverage|INFO|Dropped 1 log messages in last 73 seconds (most recently, 73 seconds ago) due to excessive rate 2022-06-20T14:52:38.648Z|01069|coverage|INFO|Skipping details of duplicate event coverage for hash=884724c9 2022-06-20T14:52:38.650Z|01070|poll_loop|INFO|Dropped 936 log messages in last 39 seconds (most recently, 37 seconds ago) due to excessive rate 2022-06-20T14:52:38.653Z|01071|poll_loop|INFO|wakeup due to [POLLIN] on fd 101 (10.0.157.93:9642<->10.0.188.6:46058) at ../lib/stream-ssl.c:836 (82% CPU usage) 2022-06-20T14:52:38.657Z|01072|poll_loop|INFO|wakeup due to [POLLIN] on fd 77 (10.0.157.93:9642<->10.0.200.65:42812) at ../lib/stream-ssl.c:836 (82% CPU usage) 2022-06-20T14:52:38.660Z|01073|poll_loop|INFO|wakeup due to [POLLIN] on fd 25 (10.0.157.93:9644<->10.0.188.134:34470) at ../lib/stream-ssl.c:836 (82% CPU usage) 2022-06-20T14:52:38.663Z|01074|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (82% CPU usage) 2022-06-20T14:52:38.668Z|01075|poll_loop|INFO|wakeup due to [POLLIN] on fd 75 (10.0.157.93:9642<->10.0.191.146:39990) at ../lib/stream-ssl.c:836 (82% CPU usage) 2022-06-20T14:52:38.671Z|01076|poll_loop|INFO|wakeup due to [POLLIN] on fd 34 (10.0.157.93:9642<->10.0.151.220:49728) at ../lib/stream-ssl.c:836 (82% CPU usage) 2022-06-20T14:52:38.684Z|01077|jsonrpc|WARN|Dropped 1 log messages in last 73 seconds (most recently, 73 seconds ago) due to excessive rate 2022-06-20T14:52:38.686Z|01078|jsonrpc|WARN|unix#2014: send error: Broken pipe 2022-06-20T14:52:39.252Z|01079|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:52:39.254Z|01080|raft|WARN|ignoring vote request received after only 2 ms (minimum election time is 16000 ms) 2022-06-20T14:52:41.681Z|01081|poll_loop|INFO|Dropped 2180 log messages in last 3 seconds (most recently, 0 seconds ago) due to excessive rate 2022-06-20T14:52:41.681Z|01082|poll_loop|INFO|wakeup due to 1-ms timeout at ../lib/reconnect.c:677 (61% CPU usage) 2022-06-20T14:52:47.680Z|01083|poll_loop|INFO|Dropped 2754 log messages in last 6 seconds (most recently, 0 seconds ago) due to excessive rate 2022-06-20T14:52:47.681Z|01084|poll_loop|INFO|wakeup due to [POLLIN] on fd 107 (10.0.157.93:9642<->10.0.188.134:36610) at ../lib/stream-ssl.c:836 (51% CPU usage) 2022-06-20T14:52:48.415Z|01085|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:52:53.775Z|01086|raft|WARN|ignoring vote request received after only 14523 ms (minimum election time is 16000 ms) 2022-06-20T14:52:55.282Z|01087|raft|INFO|server fdb3 is leader for term 12 2022-06-20T14:52:58.422Z|01088|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:53:08.419Z|01089|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:53:18.411Z|01090|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:53:28.429Z|01091|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:53:38.415Z|01092|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:53:48.413Z|01093|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:53:53.363Z|01094|raft|INFO|server 005f is leader for term 13 2022-06-20T14:53:53.458Z|01095|raft|INFO|rejecting term 12 < current term 13 received in append_request message from server fdb3 2022-06-20T14:53:58.414Z|01096|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:54:08.424Z|01097|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:54:11.573Z|01098|stream_ssl|WARN|SSL_write: system error (Connection reset by peer) 2022-06-20T14:54:11.573Z|01099|stream_ssl|WARN|SSL_write: error:1409E10F:SSL routines:ssl3_write_bytes:bad length 2022-06-20T14:54:11.573Z|01100|jsonrpc|WARN|ssl:10.0.218.171:57336: send error: Input/output error 2022-06-20T14:54:11.574Z|01101|reconnect|WARN|ssl:10.0.218.171:57336: connection dropped (Input/output error) 2022-06-20T14:54:12.468Z|01102|raft|INFO|server fdb3 is leader for term 14 2022-06-20T14:54:12.577Z|01103|raft|INFO|rejecting term 13 < current term 14 received in append_request message from server 005f 2022-06-20T14:54:18.425Z|01104|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:54:28.411Z|01105|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:54:38.415Z|01106|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:54:44.583Z|01107|raft|INFO|8ccd received "lost leadership" reply from 005f for unknown command 2022-06-20T14:54:48.402Z|01108|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:54:58.420Z|01109|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:55:06.968Z|01110|raft|INFO|term 15: 16214 ms timeout expired, starting election 2022-06-20T14:55:06.972Z|01111|raft|INFO|term 15: elected leader by 2+ of 3 servers 2022-06-20T14:55:08.370Z|01112|raft|INFO|rejecting term 14 < current term 15 received in append_request message from server fdb3 2022-06-20T14:55:08.399Z|01113|raft|INFO|rejecting term 14 < current term 15 received in vote_reply message from server fdb3 2022-06-20T14:55:08.406Z|01114|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:55:08.501Z|01115|raft|INFO|Dropped 12 log messages in last 223 seconds (most recently, 223 seconds ago) due to excessive rate 2022-06-20T14:55:08.501Z|01116|raft|INFO|current entry eid b193b579-3a99-44a0-a95c-b62154d7718c does not match prerequisite 895cb758-d16b-45cc-b5f2-1e2d9f1ec4d5 in execute_command_request 2022-06-20T14:55:08.563Z|01117|raft|INFO|current entry eid b193b579-3a99-44a0-a95c-b62154d7718c does not match prerequisite 895cb758-d16b-45cc-b5f2-1e2d9f1ec4d5 in execute_command_request 2022-06-20T14:55:08.563Z|01118|raft|INFO|current entry eid b193b579-3a99-44a0-a95c-b62154d7718c does not match prerequisite 895cb758-d16b-45cc-b5f2-1e2d9f1ec4d5 in execute_command_request 2022-06-20T14:55:08.564Z|01119|raft|INFO|current entry eid b193b579-3a99-44a0-a95c-b62154d7718c does not match prerequisite 895cb758-d16b-45cc-b5f2-1e2d9f1ec4d5 in execute_command_request 2022-06-20T14:55:08.565Z|01120|raft|INFO|current entry eid b193b579-3a99-44a0-a95c-b62154d7718c does not match prerequisite 895cb758-d16b-45cc-b5f2-1e2d9f1ec4d5 in execute_command_request 2022-06-20T14:55:27.952Z|01121|raft|WARN|ignoring vote request received as leader 2022-06-20T14:55:28.028Z|01122|raft|INFO|server 005f is leader for term 16 2022-06-20T14:55:28.080Z|01123|timeval|WARN|Unreasonably long 16151ms poll interval (15532ms user, 433ms system) 2022-06-20T14:55:28.081Z|01124|timeval|WARN|faults: 157708 minor, 0 major 2022-06-20T14:55:28.082Z|01125|timeval|WARN|disk: 0 reads, 16 writes 2022-06-20T14:55:28.084Z|01126|timeval|WARN|context switches: 0 voluntary, 286 involuntary 2022-06-20T14:55:28.085Z|01127|coverage|INFO|Skipping details of duplicate event coverage for hash=884724c9 2022-06-20T14:55:28.086Z|01128|poll_loop|INFO|Dropped 2662 log messages in last 161 seconds (most recently, 158 seconds ago) due to excessive rate 2022-06-20T14:55:28.088Z|01129|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (94% CPU usage) 2022-06-20T14:55:28.091Z|01130|poll_loop|INFO|wakeup due to [POLLOUT][POLLERR][POLLHUP] on fd 108 (10.0.157.93:9642<->) at ../lib/stream-ssl.c:802 (94% CPU usage) 2022-06-20T14:55:28.093Z|01131|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (94% CPU usage) 2022-06-20T14:55:28.100Z|01132|jsonrpc|WARN|unix#2071: send error: Broken pipe 2022-06-20T14:55:28.428Z|01133|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T14:55:28.428Z|01134|stream_ssl|WARN|SSL_write: error:1409E10F:SSL routines:ssl3_write_bytes:bad length 2022-06-20T14:55:28.429Z|01135|jsonrpc|WARN|ssl:10.0.196.167:43192: send error: Input/output error 2022-06-20T14:55:28.430Z|01136|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T14:55:28.430Z|01137|jsonrpc|WARN|ssl:10.0.188.134:41490: receive error: Protocol error 2022-06-20T14:55:28.438Z|01138|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (94% CPU usage) 2022-06-20T14:55:28.438Z|01139|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (94% CPU usage) 2022-06-20T14:55:28.441Z|01140|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T14:55:28.441Z|01141|jsonrpc|WARN|ssl:10.0.157.93:49488: send error: Broken pipe 2022-06-20T14:55:28.441Z|01142|reconnect|WARN|ssl:10.0.196.167:43192: connection dropped (Input/output error) 2022-06-20T14:55:28.441Z|01143|reconnect|WARN|ssl:10.0.188.134:41490: connection dropped (Protocol error) 2022-06-20T14:55:28.453Z|01144|poll_loop|INFO|wakeup due to [POLLIN] on fd 25 (10.0.157.93:9644<->10.0.188.134:34470) at ../lib/stream-ssl.c:836 (94% CPU usage) 2022-06-20T14:55:28.453Z|01145|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (94% CPU usage) 2022-06-20T14:55:28.453Z|01146|poll_loop|INFO|wakeup due to [POLLIN][POLLHUP] on fd 108 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:157 (94% CPU usage) 2022-06-20T14:55:28.453Z|01147|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:55:28.455Z|01148|reconnect|WARN|ssl:10.0.157.93:49488: connection dropped (Broken pipe) 2022-06-20T14:55:28.457Z|01149|poll_loop|INFO|wakeup due to [POLLIN][POLLHUP] on fd 22 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:157 (94% CPU usage) 2022-06-20T14:55:28.459Z|01150|poll_loop|INFO|wakeup due to 0-ms timeout at ../lib/stream-ssl.c:838 (94% CPU usage) 2022-06-20T14:55:38.415Z|01151|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:55:40.377Z|01152|raft|INFO|8ccd received "lost leadership" reply from fdb3 for unknown command 2022-06-20T14:55:45.598Z|01153|raft|INFO|term 17: 16023 ms timeout expired, starting election 2022-06-20T14:55:45.603Z|01154|raft|INFO|term 17: elected leader by 2+ of 3 servers 2022-06-20T14:55:45.901Z|01155|raft|INFO|rejecting term 16 < current term 17 received in append_request message from server 005f 2022-06-20T14:55:45.932Z|01156|raft|INFO|rejecting term 16 < current term 17 received in vote_reply message from server 005f 2022-06-20T14:55:45.968Z|01157|raft|INFO|Dropped 10 log messages in last 38 seconds (most recently, 38 seconds ago) due to excessive rate 2022-06-20T14:55:45.968Z|01158|raft|INFO|current entry eid 3f4b3a8e-2496-4634-a763-c5478f21acc2 does not match prerequisite 4711a19b-f313-4531-9cb9-1127680355bb in execute_command_request 2022-06-20T14:55:45.968Z|01159|raft|INFO|current entry eid 3f4b3a8e-2496-4634-a763-c5478f21acc2 does not match prerequisite 4711a19b-f313-4531-9cb9-1127680355bb in execute_command_request 2022-06-20T14:55:45.969Z|01160|raft|INFO|current entry eid 3f4b3a8e-2496-4634-a763-c5478f21acc2 does not match prerequisite 4711a19b-f313-4531-9cb9-1127680355bb in execute_command_request 2022-06-20T14:55:48.429Z|01161|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:56:10.028Z|01162|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T14:56:10.030Z|01163|jsonrpc|WARN|ssl:10.0.157.93:50828: send error: Broken pipe 2022-06-20T14:56:10.117Z|01164|raft|INFO|Dropped 17 log messages in last 24 seconds (most recently, 16 seconds ago) due to excessive rate 2022-06-20T14:56:10.118Z|01165|raft|INFO|current entry eid 4c12900e-8187-4f84-b485-82ecd19ca27c does not match prerequisite 041dd7f2-dfc7-4444-bd19-d9fc3f2ae0ad in execute_command_request 2022-06-20T14:56:10.185Z|01166|timeval|WARN|Unreasonably long 15900ms poll interval (15545ms user, 143ms system) 2022-06-20T14:56:10.187Z|01167|timeval|WARN|faults: 8683 minor, 0 major 2022-06-20T14:56:10.188Z|01168|timeval|WARN|context switches: 0 voluntary, 328 involuntary 2022-06-20T14:56:10.190Z|01169|coverage|INFO|Skipping details of duplicate event coverage for hash=884724c9 2022-06-20T14:56:10.191Z|01170|poll_loop|INFO|Dropped 70 log messages in last 42 seconds (most recently, 40 seconds ago) due to excessive rate 2022-06-20T14:56:10.194Z|01171|poll_loop|INFO|wakeup due to [POLLIN] on fd 37 (10.0.157.93:9642<->10.0.137.247:35410) at ../lib/stream-ssl.c:836 (97% CPU usage) 2022-06-20T14:56:10.197Z|01172|poll_loop|INFO|wakeup due to [POLLIN] on fd 70 (10.0.157.93:9642<->10.0.138.94:47982) at ../lib/stream-ssl.c:836 (97% CPU usage) 2022-06-20T14:56:10.200Z|01173|poll_loop|INFO|wakeup due to [POLLIN] on fd 25 (10.0.157.93:9644<->10.0.188.134:34470) at ../lib/stream-ssl.c:836 (97% CPU usage) 2022-06-20T14:56:10.201Z|01174|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (97% CPU usage) 2022-06-20T14:56:10.205Z|01175|poll_loop|INFO|wakeup due to [POLLIN] on fd 95 (10.0.157.93:9642<->10.0.201.233:48908) at ../lib/stream-ssl.c:836 (97% CPU usage) 2022-06-20T14:56:10.209Z|01176|poll_loop|INFO|wakeup due to [POLLIN] on fd 83 (10.0.157.93:9642<->10.0.206.100:53230) at ../lib/stream-ssl.c:836 (97% CPU usage) 2022-06-20T14:56:10.213Z|01177|poll_loop|INFO|wakeup due to [POLLIN] on fd 69 (10.0.157.93:9642<->10.0.152.165:34084) at ../lib/stream-ssl.c:836 (97% CPU usage) 2022-06-20T14:56:10.223Z|01178|jsonrpc|WARN|unix#2084: send error: Broken pipe 2022-06-20T14:56:10.242Z|01179|reconnect|WARN|ssl:10.0.157.93:50828: connection dropped (Broken pipe) 2022-06-20T14:56:10.243Z|01180|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T14:56:10.245Z|01181|jsonrpc|WARN|ssl:10.0.188.134:42360: send error: Broken pipe 2022-06-20T14:56:10.246Z|01182|reconnect|WARN|ssl:10.0.188.134:42360: connection dropped (Broken pipe) 2022-06-20T14:56:10.285Z|01183|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T14:56:10.286Z|01184|jsonrpc|WARN|ssl:10.0.196.167:44276: receive error: Protocol error 2022-06-20T14:56:10.289Z|01185|raft|INFO|current entry eid 4c12900e-8187-4f84-b485-82ecd19ca27c does not match prerequisite 041dd7f2-dfc7-4444-bd19-d9fc3f2ae0ad in execute_command_request 2022-06-20T14:56:10.529Z|01186|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:56:10.531Z|01187|reconnect|WARN|ssl:10.0.196.167:44276: connection dropped (Protocol error) 2022-06-20T14:56:17.923Z|01188|raft|INFO|8ccd received "lost leadership" reply from 005f for unknown command 2022-06-20T14:56:18.425Z|01189|ovsdb_server|INFO|memory trimming after compaction enabled. 2022-06-20T14:56:23.834Z|01190|raft|INFO|Dropped 104 log messages in last 14 seconds (most recently, 14 seconds ago) due to excessive rate 2022-06-20T14:56:23.834Z|01191|raft|INFO|current entry eid 76daeb73-06e6-4aa2-8299-c66686d65f94 does not match prerequisite a489bf8a-06c6-4175-b94c-6236eb52a283 in execute_command_request 2022-06-20T14:56:43.892Z|01192|raft|WARN|ignoring vote request received as leader 2022-06-20T14:56:43.945Z|01193|raft|INFO|server 005f is leader for term 18 2022-06-20T14:56:44.026Z|01194|timeval|WARN|Unreasonably long 16038ms poll interval (15719ms user, 144ms system) 2022-06-20T14:56:44.028Z|01195|timeval|WARN|faults: 1756 minor, 0 major 2022-06-20T14:56:44.029Z|01196|timeval|WARN|disk: 0 reads, 16 writes 2022-06-20T14:56:44.031Z|01197|timeval|WARN|context switches: 0 voluntary, 231 involuntary 2022-06-20T14:56:44.032Z|01198|coverage|INFO|Skipping details of duplicate event coverage for hash=884724c9 2022-06-20T14:56:44.033Z|01199|poll_loop|INFO|Dropped 80 log messages in last 34 seconds (most recently, 32 seconds ago) due to excessive rate 2022-06-20T14:56:44.037Z|01200|poll_loop|INFO|wakeup due to [POLLIN] on fd 25 (10.0.157.93:9644<->10.0.188.134:34470) at ../lib/stream-ssl.c:836 (93% CPU usage) 2022-06-20T14:56:44.040Z|01201|poll_loop|INFO|wakeup due to [POLLIN] on fd 23 (/var/run/ovn/ovnsb_db.ctl<->) at ../lib/stream-fd.c:274 (93% CPU usage) 2022-06-20T14:56:44.044Z|01202|poll_loop|INFO|wakeup due to [POLLOUT][POLLERR][POLLHUP] on fd 108 (10.0.157.93:9642<->) at ../lib/stream-ssl.c:802 (93% CPU usage) 2022-06-20T14:56:44.048Z|01203|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (93% CPU usage) 2022-06-20T14:56:44.060Z|01204|jsonrpc|WARN|unix#2091: send error: Broken pipe 2022-06-20T14:56:44.064Z|01205|jsonrpc|WARN|unix#2092: send error: Broken pipe 2022-06-20T14:56:44.068Z|01206|jsonrpc|WARN|unix#2093: send error: Broken pipe 2022-06-20T14:56:44.353Z|01207|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T14:56:44.354Z|01208|stream_ssl|WARN|SSL_write: error:1409E10F:SSL routines:ssl3_write_bytes:bad length 2022-06-20T14:56:44.354Z|01209|jsonrpc|WARN|ssl:10.0.196.167:44982: send error: Input/output error 2022-06-20T14:56:44.355Z|01210|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T14:56:44.355Z|01211|jsonrpc|WARN|ssl:10.0.188.134:43234: receive error: Protocol error 2022-06-20T14:56:44.359Z|01212|poll_loop|INFO|wakeup due to [POLLIN] on fd 32 (0.0.0.0:9642<->) at ../lib/stream-ssl.c:972 (93% CPU usage) 2022-06-20T14:56:44.361Z|01213|stream_ssl|WARN|SSL_write: system error (Broken pipe) 2022-06-20T14:56:44.361Z|01214|reconnect|WARN|ssl:10.0.196.167:44982: connection dropped (Input/output error) 2022-06-20T14:56:44.362Z|01215|reconnect|WARN|ssl:10.0.188.134:43234: connection dropped (Protocol error) 2022-06-20T14:56:44.363Z|01216|stream_ssl|WARN|SSL_accept: system error (Success) 2022-06-20T14:56:44.366Z|01217|reconnect|WARN|ssl:10.0.157.93:50596: connection dropped (Broken pipe) 2022-06-20T14:56:44.366Z|01218|reconnect|WARN|ssl:10.0.157.93:51864: connection dropped (Protocol error) 2022-06-20T14:56:46.524Z|01219|poll_loop|INFO|Dropped 59 log messages in last 2 seconds (most recently, 0 seconds ago) due to excessive rate 2022-06-20T14:56:46.525Z|01220|poll_loop|INFO|wakeup due to 551-ms timeout at ../ovsdb/ovsdb-server.c:296 (93% CPU usage) 2022-06-20T14:56:48.425Z|01221|ovsdb_server|INFO|memory trimming after compaction enabled. We are seeing 16seconds pill internal on SBDB. I will need to pass this bug to the OVN team for further in depth analysis to see what's happening.
So the problem IMHO is not that this is happening, but at least once pods get stacked up, I'd expect them to slowly get created and controllers to bind ports one by one even if it takes order of minutes. However SBDB hits the wall and then controllers never recover... I'm thinking, did the northd parallelization now push the bottleneck towards sbdb to the point where its not able to keep up? Because apparently these problems don't exist in 4.10.0 cluster. I will talk to the OVN team tomorrow to see what needs to be done here.
Hi, tech writer here. It doesn't look like there is a workaround documented for this issue - can you please confirm?
OpenShift has moved to Jira for its defect tracking! This bug can now be found in the OCPBUGS project in Jira. https://issues.redhat.com/browse/OCPBUGS-9825