Openebs: kubelet seen consuming high RAM during iSCSI connection establishment.

[vishnuitta]

kubelet triggers iscsiadm command to discover LUNs and reads the output of the command until it exists.
Due to the issue mentioned here https://github.com/open-iscsi/open-iscsi/issues/155, kubelet ends up consuming high CPU and RAM.

[AmitKumarDas]

Below is one of the user's setup that has this error:

General overview of setup:
- 3 machines, 2x quad-core hyperthread/node, 24GB RAM/node, 16x SAS 146GB HDDs/node
- All nodes are master, etcd, and worker
- Fedora 29
- Kubespray/Kube 1.12.4
- Docker 128.06.1-ce via Fedora 28 Docker repos
- Rancher via helm
- Helm/metrics server/Dashboard/nginx ingress via kubespray
- Cert manager/certs via custom script
- MetalLB installed
- kubectl 1.13 via workstation

General Process:
- Run kubespray
- Copy credentials file from server to workstation
- Make sure helm works
- Run rancher-init.sh
- Run kuberang, make sure it passes
- Install MetalLB
- Install OpenEBS
- Use Rancher's catalog apps to install "efk" and Prometheus using imported config from files

[AmitKumarDas]

These are the details from another user w.r.t this issue:

UseCase:

We attach 1 elastic block storage disk to each of the worker nodes in the cluster (3 in this case). We utilize Kubespray to deploy our clusters and helm to install OpenEBS (v0.8.0) after the clusters are up. I can deploy a few applications with PVC's that utilize the OpenEBS storage. We run into issues sometimes when we re-deploy an application (or delete the application pod to restart) with helm and it needs to use the existing PVC.

Observed Issue:

It appears that the iscsiadm command that kubelet runs (iscsiadm -m discoverydb -t sendtargets -p 10.233.46.76 3260 -I default --discover) continuously fails and repeats rapidly. For some reason this causes the memory consumption of kubelet to grow until the node goes out-of-memory and needs to be rebooted.

I have noticed that killing the iscsiadm discoverydb process stops the kubelet's memory consumption from growing.

The issue is not always reproducible. It seems to happen when trying to re-attach a PVC to a pod. Freshly created PVC's seem to attach normally.

As for network delays: We do not currently monitor any network bandwidth/latency, but our loads are these clusters are fairly low. I ran into the issue on a brand new Kubernetes cluster yesterday ( on packet.net). Until now i have never questioned their network infrastructure.

We utilize helm frequently to create/delete/upgrade deployments, but we usually keep the same PVC.

Environment Details:

Clusters on packet.net
OS=CoreOS
Kubernetes Version: 1.13.1
CoreOS Version: VERSION=2037.0.0
Linux Kernel: 4.19 (required for our product)
No additional iSCSI packages were installed
iscsiadm version 2.0-873
default iscsid config

Logs from journalctl and the cstor-istgt container to follow:

jourctl logs snippet:

Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: failed to send SendTargets PDU
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: connection login retries (reopen_max) 5 exceeded
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: Connection to Discovery Address 10.233.46.76 failed
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: failed to send SendTargets PDU
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: connection login retries (reopen_max) 5 exceeded
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: Connection to Discovery Address 10.233.46.76 failed
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: failed to send SendTargets PDU
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: connection login retries (reopen_max) 5 exceeded
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: Connection to Discovery Address 10.233.46.76 failed
Feb 06 06:11:38 <hostname> kubelet[1063]: iscsiadm: failed to send SendTargets PDU



cstor-istgt snippet:

2019-02-05/15:43:30.250 worker            :6088: c#0.140005771040512.: iscsi_read_pdu() EOF

2019-02-05/15:43:30.250 sender            :5852: s#0.140005666154240.: sender loop ended (0:14:43084)

2019-02-05/15:43:30.251 worker            :6292: c#0.140005771040512.: worker 0/-1/43084 end (c#0.140005771040512/s#0.140005666154240)
2019-02-05/15:43:30.264 worker            :5885: c#1.140005666154240.: con:1/16 [8d614b93:43088->10.233.45.100:3260,1]
2019-02-05/15:43:30.531 istgt_iscsi_op_log:1923: c#1.140005666154240.: login failed, target not ready

2019-02-05/15:43:30.782 worker            :6088: c#1.140005666154240.: iscsi_read_pdu() EOF

2019-02-05/15:43:30.782 sender            :5852: s#1.140005649413888.: sender loop ended (1:16:43088)

2019-02-05/15:43:30.783 worker            :6292: c#1.140005666154240.: worker 1/-1/43088 end (c#1.140005666154240/s#1.140005649413888)
2019-02-05/15:43:33.285 worker            :5885: c#2.140005649413888.: con:2/18 [8d614b93:43092->10.233.45.100:3260,1]
2019-02-05/15:43:33.536 istgt_iscsi_op_log:1923: c#2.140005649413888.: login failed, target not ready

2019-02-05/15:43:33.787 worker            :6088: c#2.140005649413888.: iscsi_read_pdu() EOF

2019-02-05/15:43:33.787 sender            :5852: s#2.140005632636672.: sender loop ended (2:18:43092)

2019-02-05/15:43:33.788 worker            :6292: c#2.140005649413888.: worker 2/-1/43092 end (c#2.140005649413888/s#2.140005632636672)
2019-02-05/15:43:35.251 istgt_remove_conn :7039: c#0.140005771040512.: remove_conn->initiator:147.75.97.141(iqn.2019-02.net.packet:device.7c8ad781) Target: 10.233.109.82(dummy LU0) conn:0x7f55a4c18000:0 tsih:1 connections:0  IOPending=0
2019-02-05/15:43:36.291 worker            :5885: c#0.140005666154240.: con:0/14 [8d614b93:43094->10.233.45.100:3260,1]
2019-02-05/15:43:36.540 istgt_iscsi_op_log:1923: c#0.140005666154240.: login failed, target not ready

2019-02-05/15:43:36.791 worker            :6088: c#0.140005666154240.: iscsi_read_pdu() EOF

2019-02-05/15:43:36.791 sender            :5852: s#0.140005771040512.: sender loop ended (0:14:43094)

[kmova]

There is work to be done in K8s (kubelet) from hogging the RAM/CPU of the node when the commands it executes results in generating too many logs. This is being tracked by: https://github.com/kubernetes/kubernetes/issues/70890

[kmova]

The timeout of iscsiadm discovery command was being caused by cstor target, failing to read the discovery packet that arrived few ms later after the initial connection. This was tracked down to the socket readv call being made with SO_RCVLOWAT set to 48. After setting the value to default 1, the readv calls are not blocked. As it turned out, there is a difference in OS/Kernel in handling the readv calls, where data is split cross multiple PDUs.

This was a very hard issue to reproduce and many many thanks to @proegssilb for helping with his time and setup in tracking down the issue and validating with a debug build with the fix. https://github.com/openebs/istgt/commit/5df6ec1915cdc8186f48211ababe04e8bbda74d6

[kmova]

The test program used to check how the OS handles delayed packets when SO_RCVLOWAT is set is available here. https://github.com/pawanpraka1/gist

When running this program by simulating the network condition of delayed packet arrivals - the read calls are getting blocked. A issue for this is raised on Fedora at: https://bugzilla.redhat.com/show_bug.cgi?id=1679565

We have verified that the issue doesn't exist on Ubuntu and RedHat.

[kmova]

The cstor target has been updated to work with slow receiving iscsi PDUs.