0%

问题背景

karaf框架没有直接依赖log4j包,所以简单的升级项目中的log4j或实际项目中没有log4j,都无法解决最近发现的漏洞问题(CVE-2021-44228CVE-2021-45046CVE-2021-45046)。

分析过程

分析发现,karaf框架实际依赖的日志包是org.ops4j.pax.logging.xxx,而org.ops4j.pax.logging.xxx依赖了log4j,相当于做了一层包装。所以,要解决漏洞,有三种升级方式:

  1. 升级框架:这个影响就比较大了,而且框架的版本发布周期比较慢,目前还没有编译好的框架包,要升级框架就需要自己编译出所有的框架包,风险较大;
  2. 升级依赖包:影响较小,如果没有配置依赖包的地方,可能无法升级;(实际确认,无法单独升级)
  3. 修改当前版本依赖包并重新编译:影响较小,如果与最新版本跨度较大,可能修改点会很多;

综合比较,考虑使用第3个方案走走看,从参考资料[1]的代码提交记录看,org.ops4j.pax.logging为了解决log4j漏洞,仅涉及依赖包log4j的版本升级,版本跨度是从1.11.9升级到1.11.12,跨度不大,实际有哪些修改点,先编译看看有没有问题:

1
2
3
4
5
6
7
8
9
pom.xml
<version.org.apache.felix.configadmin>1.9.20</version.org.apache.felix.configadmin>
<version.org.apache.felix.framework>5.6.12</version.org.apache.felix.framework>
<version.org.apache.felix6.framework>6.0.3</version.org.apache.felix6.framework>
- <version.org.apache.logging.log4j>2.16.0</version.org.apache.logging.log4j>
+ <version.org.apache.logging.log4j>2.17.0</version.org.apache.logging.log4j>
<version.org.apache.servicemix.bundles.javax-inject>1_3</version.org.apache.servicemix.bundles.javax-inject>
<version.org.jboss.logging>3.4.1.Final</version.org.jboss.logging>
<version.org.mockito>3.7.7</version.org.mockito>

下载当前使用的版本,从源码的各模块看,可能需要jdk9

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
[root@node org.ops4j.pax.logging-logging-1.11.9]# ll
total 144
-rw-r--r-- 1 root root 939 Feb 23 2021 CONTRIBUTORS.txt
-rw-r--r-- 1 root root 755 Feb 23 2021 license-header.txt
-rw-r--r-- 1 root root 12525 Feb 23 2021 LICENSE.txt
drwxr-xr-x 4 root root 99 Dec 21 17:51 pax-logging-api
drwxr-xr-x 4 root root 46 Dec 21 17:51 pax-logging-api-java9
drwxr-xr-x 4 root root 46 Dec 21 17:51 pax-logging-it
drwxr-xr-x 6 root root 106 Feb 23 2021 pax-logging-it-karaf
drwxr-xr-x 4 root root 99 Dec 21 17:51 pax-logging-log4j2
drwxr-xr-x 4 root root 99 Dec 21 17:51 pax-logging-log4j2-extra
drwxr-xr-x 4 root root 99 Dec 21 17:51 pax-logging-logback
drwxr-xr-x 2 root root 21 Feb 23 2021 pax-logging-report
drwxr-xr-x 10 root root 166 Feb 23 2021 pax-logging-samples
drwxr-xr-x 4 root root 99 Dec 21 17:51 pax-logging-service
-rw-r--r-- 1 root root 46604 Dec 21 17:46 pom.xml
-rw-r--r-- 1 root root 67356 Feb 23 2021 readme.adoc
drwxr-xr-x 3 root root 18 Feb 23 2021 src

先下载个maven:3.3.9-jdk-9编译镜像试试:

1
2
3
4
5
6
7
[root@node]# docker pull maven:3.3.9-jdk-9
3.3.9-jdk-9: Pulling from library/maven
...
2ce3b259f3e2: Pull complete
Digest: sha256:ad6b04c52e7f83c05e8840e0b1de0c39ba097c1e40efb294e740db303468cbe8
Status: Downloaded newer image for maven:3.3.9-jdk-9
docker.io/library/maven:3.3.9-jdk-9

启动编译,先尝试编译原始版本:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
[root@node]# docker run -it -v /home:/home docker.io/library/maven:3.3.9-jdk-9 bash
root@aae0956cb558:/home# cd org.ops4j.pax.logging-logging-1.11.9
root@aae0956cb558:/home/org.ops4j.pax.logging-logging-1.11.9# mvn clean install -Dmaven.test.skip=true
[INFO] Scanning for projects...
[WARNING] Error injecting: org.apache.maven.wagon.providers.http.HttpWagon
java.lang.ExceptionInInitializerError
at java.base/javax.crypto.JceSecurityManager.<clinit>(JceSecurityManager.java:66)
at java.base/javax.crypto.Cipher.getConfiguredPermission(Cipher.java:2610)
at java.base/javax.crypto.Cipher.getMaxAllowedKeyLength(Cipher.java:2634)
...
Caused by: java.lang.SecurityException: Can not initialize cryptographic mechanism
at java.base/javax.crypto.JceSecurity.<clinit>(JceSecurity.java:118)
... 96 more
Caused by: java.lang.SecurityException: Can't read cryptographic policy directory: unlimited
at java.base/javax.crypto.JceSecurity.setupJurisdictionPolicies(JceSecurity.java:324)
at java.base/javax.crypto.JceSecurity.access$000(JceSecurity.java:73)
at java.base/javax.crypto.JceSecurity$1.run(JceSecurity.java:109)
at java.base/javax.crypto.JceSecurity$1.run(JceSecurity.java:106)
at java.base/java.security.AccessController.doPrivileged(Native Method)
at java.base/javax.crypto.JceSecurity.<clinit>(JceSecurity.java:105)
... 96 more

参考资料[2],问题出在编译镜像的$JAVA_HOME/conf命令下找不到一个安全相关的配置文件,查看一下发现conf文件夹都不存在,说明编译镜像有问题:

1
2
3
4
5
6
7
8
root@aae0956cb558:/home/org.ops4j.pax.logging-logging-1.11.9# env
JAVA_HOME=/usr/lib/jvm/java-9-openjdk-amd64

root@aae0956cb558:/home/org.ops4j.pax.logging-logging-1.11.9# ls /usr/lib/jvm/java-9-openjdk-amd64
bin docs include jmods legal lib man src.zip

//正常情况下$JAVA_HOME/conf目录下有以下文件
java-9-openjdk logging.properties management net.properties security sound.properties

那就换个新版本试试,下载maven:3.6-openjdk-11编译镜像:

1
2
3
4
5
6
[root@node]# docker pull maven:3.6-openjdk-11
3.6-openjdk-11: Pulling from library/maven
...s
Digest: sha256:1d29ccf46ef2a5e64f7de3d79a63f9bcffb4dc56be0ae3daed5ca5542b38aa2d
Status: Downloaded newer image for maven:3.6-openjdk-11
docker.io/library/maven:3.6-openjdk-11

启动编译:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
[root@node]# docker run -it -v /home:/home maven:3.6-openjdk-11 bash
root@ff2407bc2d9e:/# cd /home/org.ops4j.pax.logging-logging-1.11.9
root@ff2407bc2d9e:/home/org.ops4j.pax.logging-logging-1.11.9# mvn clean install -Dmaven.test.skip=true
[INFO] Scanning for projects...
Downloading from knopflerfish: http://resources.knopflerfish.org/repo/maven2/release/org/ops4j/master/4.3.0/master-4.3.0.pom
...
[INFO]
[INFO] --- maven-clean-plugin:3.1.0:clean (default-clean) @ pax-logging-api-java9 ---
[INFO]
[INFO] --- maven-enforcer-plugin:3.0.0-M1:enforce (enforce-maven) @ pax-logging-api-java9 ---
[INFO]
[INFO] --- maven-toolchains-plugin:3.0.0:toolchain (default) @ pax-logging-api-java9 ---
[INFO] Required toolchain: jdk [ version='[9, )' ]
[ERROR] No toolchain found for type jdk
[ERROR] Cannot find matching toolchain definitions for the following toolchain types:
jdk [ version='[9, )' ]
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary for OPS4J Pax Logging (Build POM) 1.11.9:
[INFO]
[INFO] OPS4J Pax Logging (Build POM) ...................... SUCCESS [ 35.399 s]
[INFO] OPS4J Pax Logging - API (Java9) .................... FAILURE [ 10.045 s]
...
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-toolchains-plugin:3.0.0:toolchain (default) on project pax-logging-api-java9: Cannot find matching toolchain definitions for the following toolchain types:
[ERROR] jdk [ version='[9, )' ]
[ERROR] Please make sure you define the required toolchains in your ~/.m2/toolchains.xml file.

第一个问题解决了,但从报错信息看,应该是要求jdk9的版本,那就再换一个maven:3.5-jdk-9-slim镜像:

1
2
3
4
5
6
7
[root@node]# docker pull maven:3.5-jdk-9-slim
3.5-jdk-9-slim: Pulling from library/maven
...
7afb9733d3e4: Pull complete
Digest: sha256:f5d85a2b5498c0a36a6515722e108969ff2fcfec5bef6c8ef83c8ebc4b671af1
Status: Downloaded newer image for maven:3.5-jdk-9-slim
docker.io/library/maven:3.5-jdk-9-slim

继续编译:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
[root@node]# docker run -it -v /home:/home docker.io/library/maven:3.5-jdk-9-slim  bash
root@895be557c3cd:/# cd /home/org.ops4j.pax.logging-logging-1.11.9
root@895be557c3cd:/home/org.ops4j.pax.logging-logging-1.11.9# mvn clean install -Dmaven.test.skip=true
[INFO] Scanning for projects...
Downloading from knopflerfish: http://resources.knopflerfish.org/repo/maven2/release/org/ops4j/master/4.3.0/master-4.3.0.pom
...
[INFO]
[INFO] --- maven-clean-plugin:3.1.0:clean (default-clean) @ pax-logging-api-java9 ---
[INFO]
[INFO] --- maven-enforcer-plugin:3.0.0-M1:enforce (enforce-maven) @ pax-logging-api-java9 ---
[INFO]
[INFO] --- maven-toolchains-plugin:3.0.0:toolchain (default) @ pax-logging-api-java9 ---
[INFO] Required toolchain: jdk [ version='[9, )' ]
[ERROR] No toolchain found for type jdk
[ERROR] Cannot find matching toolchain definitions for the following toolchain types:
jdk [ version='[9, )' ]
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] OPS4J Pax Logging (Build POM) 1.11.9 ............... SUCCESS [01:27 min]
[INFO] OPS4J Pax Logging - API (Java9) .................... FAILURE [ 17.560 s]
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-toolchains-plugin:3.0.0:toolchain (default) on project pax-logging-api-java9: Cannot find matching toolchain definitions for the following toolchain types:
[ERROR] jdk [ version='[9, )' ]
[ERROR] Please make sure you define the required toolchains in your ~/.m2/toolchains.xml file.

当前编译镜像已经符合要求了,但依然报错,参考资料[3],需要在~/.m2/目录下创建toolchains.xml文件并做相关配置:

通过env命令查看java的相关环境变量:

1
2
3
4
5
6
root@895be557c3cd:/home/org.ops4j.pax.logging-logging-1.11.9# env
...
JAVA_HOME=/docker-java-home
JAVA_VERSION=9.0.4+12
JAVA_DEBIAN_VERSION=9.0.4+12-4
...

修改versionjdkHome字段:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

root@895be557c3cd:/home/org.ops4j.pax.logging-logging-1.11.9# cat ~/.m2/toolchains.xml
<?xml version="1.0" encoding="UTF-8"?>
<toolchains xmlns="http://maven.apache.org/TOOLCHAINS/1.1.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://maven.apache.org/TOOLCHAINS/1.1.0 http://maven.apache.org/xsd/toolchains-1.1.0.xsd">
<toolchain>
<type>jdk</type>
<provides>
<version>9</version>
<vendor>oracle</vendor>
</provides>
<configuration>
<jdkHome>/docker-java-home</jdkHome>
</configuration>
</toolchain>
</toolchains>

继续编译:

1
2
3
4
5
6
7
8
9
10
11
root@895be557c3cd:/home/org.ops4j.pax.logging-logging-1.11.9# mvn clean install -Dmaven.test.skip=true
[INFO] Scanning for projects...
[INFO] Inspecting build with total of 19 modules...
[INFO] Installing Nexus Staging features:
[INFO] ... total of 19 executions of maven-deploy-plugin replaced with nexus-staging-maven-plugin
[INFO] Reactor Summary:
[INFO]
[INFO] OPS4J Pax Logging (Build POM) 1.11.9 ............... SUCCESS [ 0.335 s]
[INFO] OPS4J Pax Logging - API (Java9) .................... SUCCESS [ 40.867 s]
[INFO] OPS4J Pax Logging - API ............................ SUCCESS [ 51.690 s]
[INFO] OPS4J Pax Logging - API tests ...................... FAILURE [02:11 min]

失败在test模块,测试模块不影响,修改pom.xml注释掉即可;

再编译:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
root@895be557c3cd:/home/org.ops4j.pax.logging-logging-1.11.9# mvn clean install -Dmaven.test.skip=true
...
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] OPS4J Pax Logging (Build POM) 1.11.9 ............... SUCCESS [ 0.275 s]
[INFO] OPS4J Pax Logging - API (Java9) .................... SUCCESS [ 1.873 s]
[INFO] OPS4J Pax Logging - API ............................ SUCCESS [ 4.672 s]
[INFO] OPS4J Pax Logging - Log4Jv1 implementation ......... SUCCESS [ 39.435 s]
[INFO] OPS4J Pax Logging - Log4Jv2 implementation ......... SUCCESS [ 8.208 s]
[INFO] OPS4J Pax Logging - Log4j v2 Extra packages ........ SUCCESS [ 0.131 s]
[INFO] OPS4J Pax Logging - Logback implementation ......... SUCCESS [ 15.241 s]
[INFO] OPS4J Pax Logging - Integration Tests .............. SUCCESS [01:48 min]
[INFO] OPS4J Pax Logging - Karaf .......................... SUCCESS [ 0.014 s]
[INFO] OPS4J Pax Logging - Karaf KAR Logger ............... SUCCESS [ 0.148 s]
[INFO] OPS4J Pax Logging - Karaf KAR ...................... SUCCESS [ 28.098 s]
[INFO] OPS4J Pax Logging - Karaf Distribution ............. SUCCESS [ 2.002 s]
[INFO] OPS4J Pax Logging - Karaf Integration Tests 1.11.9 . SUCCESS [ 36.557 s]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 04:07 min
[INFO] Finished at: 2021-12-21T09:45:18Z
[INFO] ------------------------------------------------------------------------

不容易,终于成功了!开始修改pod.xml,把依赖的log4j包升级上去:

1
2
- <version.org.apache.logging.log4j>2.14.0</version.org.apache.logging.log4j>
+ <version.org.apache.logging.log4j>2.17.0</version.org.apache.logging.log4j>

编译:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
root@895be557c3cd:/home/org.ops4j.pax.logging-logging-1.11.9# mvn clean install -Dmaven.test.skip=true
[INFO] Scanning for projects...
[INFO] Inspecting build with total of 13 modules...
[INFO] Installing Nexus Staging features:
[INFO] ... total of 13 executions of maven-deploy-plugin replaced with nexus-staging-maven-plugin
[INFO] ------------------------------------------------------------------------
...
[ERROR] COMPILATION ERROR :
[INFO] -------------------------------------------------------------
[ERROR] /home/org.ops4j.pax.logging-logging-1.11.9/pax-logging-log4j2/src/main/java/org/apache/logging/log4j/core/impl/ThrowableProxy.java:[85,54] cannot find symbol
symbol: variable EMPTY_THROWABLE_PROXY_ARRAY
location: class org.apache.logging.log4j.core.impl.ThrowableProxyHelper
[INFO] 1 error
[INFO] -------------------------------------------------------------
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] OPS4J Pax Logging (Build POM) 1.11.9 ............... SUCCESS [ 0.302 s]
[INFO] OPS4J Pax Logging - API (Java9) .................... SUCCESS [ 1.836 s]
[INFO] OPS4J Pax Logging - API ............................ SUCCESS [ 10.592 s]
[INFO] OPS4J Pax Logging - Log4Jv1 implementation ......... SUCCESS [ 2.017 s]
[INFO] OPS4J Pax Logging - Log4Jv2 implementation ......... FAILURE [ 4.279 s]

又报错了,找到官方升级过log4j的版本,发现ThrowableProxy方法的构造方法里suppressedProxies字段的赋值有变化,老版本是ThrowableProxyHelper.EMPTY_THROWABLE_PROXY_ARRAY,而新版本变成了ThrowableProxy.EMPTY_ARRAY。问题不大,改一下就行;

1
2
3
4
5
6
7
8
9
10
11
12
src/main/java/org/apache/logging/log4j/core/impl/ThrowableProxy.java
public class ThrowableProxy implements Serializable {
static final ThrowableProxy[] EMPTY_ARRAY = {};
ThrowableProxy() {
this.throwable = null;
this.name = null;
this.extendedStackTrace = ExtendedStackTraceElement.EMPTY_ARRAY;
this.causeProxy = null;
this.message = null;
this.localizedMessage = null;
this.suppressedProxies = ThrowableProxy.EMPTY_ARRAY;
}

再次编译:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
root@895be557c3cd:/home/org.ops4j.pax.logging-logging-1.11.9# mvn clean install -Dmaven.test.skip=true
[INFO] Scanning for projects...
[INFO] Inspecting build with total of 13 modules...
[INFO] Installing Nexus Staging features:
[INFO] ... total of 13 executions of maven-deploy-plugin replaced with nexus-staging-maven-plugin
[INFO] ------------------------------------------------------------------------
[INFO] Reactor Summary:
[INFO]
[INFO] OPS4J Pax Logging (Build POM) 1.11.9 ............... SUCCESS [ 0.290 s]
[INFO] OPS4J Pax Logging - API (Java9) .................... SUCCESS [ 1.819 s]
[INFO] OPS4J Pax Logging - API ............................ SUCCESS [ 4.717 s]
[INFO] OPS4J Pax Logging - Log4Jv1 implementation ......... SUCCESS [ 2.057 s]
[INFO] OPS4J Pax Logging - Log4Jv2 implementation ......... SUCCESS [ 2.654 s]
[INFO] OPS4J Pax Logging - Log4j v2 Extra packages ........ SUCCESS [ 0.144 s]
[INFO] OPS4J Pax Logging - Logback implementation ......... SUCCESS [ 0.908 s]
[INFO] OPS4J Pax Logging - Integration Tests .............. SUCCESS [ 4.402 s]
[INFO] OPS4J Pax Logging - Karaf .......................... SUCCESS [ 0.012 s]
[INFO] OPS4J Pax Logging - Karaf KAR Logger ............... SUCCESS [ 0.138 s]
[INFO] OPS4J Pax Logging - Karaf KAR ...................... SUCCESS [ 1.588 s]
[INFO] OPS4J Pax Logging - Karaf Distribution ............. SUCCESS [ 2.114 s]
[INFO] OPS4J Pax Logging - Karaf Integration Tests 1.11.9 . SUCCESS [ 0.163 s]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 23.440 s
[INFO] Finished at: 2021-12-21T09:51:37Z
[INFO] ------------------------------------------------------------------------

升级log4j的版本编译成功。

解决方案

把新编译的pax-logging-apipax-logging-log4j替换到依赖仓库中,重新编译交付件,验证漏洞解决,日志功能正常。

参考资料

  1. https://github.com/ops4j/org.ops4j.pax.logging
  2. https://github.com/docker-library/openjdk/issues/101
  3. https://blog.csdn.net/yiqiu3812/article/details/103298980

本次发现的问题是踩到了老版本Kubernetes的坑,查找资料发现fatedier大佬已经做了很棒的分析,此处转载过来仅做学习记录。

作者:fatedier
本文出处:https://blog.fatedier.com/2020/04/17/pod-loopcrash-of-k8s-subpath/
文章版权归本人所有,欢迎转载,但未经作者同意必须保留此段声明,且在文章页面明显位置给出原文链接,否则保留追究法律责任的权利。

问题背景

Kubernetes对于挂载了 subpath 的容器,在 configmap 或其他 volume 变更后,如果容器因为意外退出后,就会持续crash,无法正常启动。

社区相关 issue #68211,问题已经在v1.19版本解决。

分析过程

复现步骤

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
---
apiVersion: v1
kind: Pod
metadata:
name: test-pod
spec:
volumes:
- configMap:
name: extra-cfg
name: extra-cfg
containers:
- name: test
image: ubuntu:bionic
command: ["sleep", "30"]
resources:
requests:
cpu: 100m
volumeMounts:
- name: extra-cfg
mountPath: /etc/extra.ini
subPath: extra.ini
---
apiVersion: v1
data:
extra.ini: |
somedata
kind: ConfigMap
metadata:
name: extra-cfg

Apply 此配置,Pod 启动完成后,修改 configmap 的内容,等待 30 秒后容器自动退出,kubelet 重启容器,此时观察到容器持续 mount 失败。

1
Error: failed to start container "test": Error response from daemon: OCI runtime create failed: container_linux.go:345: starting container process caused "process_linux.go:424: container init caused \"rootfs_linux.go:58: mounting \\\"/var/lib/kubelet/pods/e044883a-48da-4d28-b304-1a57dcb32203/volume-subpaths/extra-cfg/test/0\\\" to rootfs \\\"/var/lib/docker/overlay2/31b076d0012aad47aa938b482de24ecda8b41505489a22f63b8a3e4ce39b43ba/merged\\\" at \\\"/var/lib/docker/overlay2/31b076d0012aad47aa938b482de24ecda8b41505489a22f63b8a3e4ce39b43ba/merged/etc/extra.ini\\\" caused \\\"no such file or directory\\\"\"": unknown

原因分析

Configmap Volume 的更新

当容器第一次启动前,kubelet 先将 configmap 中的内容下载到 Pod 对应的 Volume 目录下,例如 /var/lib/kubelet/pods/{Pod UID}/volumes/kubernetes.io~configmap/extra-cfg

同时为了保证对此 volume 下内容的更新是原子的(更新目录时),所以会通过软链接的方式进行更新,目录中文件如下。

1
2
3
4
5
drwxrwxrwx 3 root root 4.0K Mar 29 03:12 .
drwxr-xr-x 3 root root 4.0K Mar 29 03:12 ..
drwxr-xr-x 2 root root 4.0K Mar 29 03:12 ..2020_03_29_03_12_44.788930127
lrwxrwxrwx 1 root root 31 Mar 29 03:12 ..data -> ..2020_03_29_03_12_44.788930127
lrwxrwxrwx 1 root root 16 Mar 29 03:12 extra.ini -> ..data/extra.ini

extra.ini..data/extra.ini 的软链,..data..2020_03_29_03_12_44.788930127 的软链,命名为时间戳的目录存放真实内容。

configmap 更新后,会生成新的时间戳的目录存放更新后的内容。

创建新的软链 ..data_tmp 指向新的时间戳目录,之后重命名为 ..data,重命名是一个原子操作。

最后删除旧的时间戳目录。

容器挂载 subpath Volume 的准备

configmap Volume 准备完成后,kubelet 会将 configmapsubpath 指定的文件 bind mount 到一个特殊的目录下: /var/lib/kubelet/pods/{Pod UID}/volume-subpaths/extra-cfg/{container name}/0

1
2
cat /proc/self/mountinfo|grep extra
2644 219 8:1 /var/lib/kubelet/pods/{Pod UID}/volumes/kubernetes.io~configmap/extra-cfg/..2020_03_29_03_12_13.444136014/extra.ini /var/lib/kubelet/pods/{Pod UID}/volume-subpaths/extra-cfg/test/0 rw,relatime shared:99 - ext4 /dev/sda1 rw,data=ordered

可以看出,bind mount 的文件其实是真实文件的时间戳目录下的内容。

Configmap 更新后,此时间戳目录会被删除,源文件加上了 //deleted

1
2
cat /proc/self/mountinfo|grep extra
2644 219 8:1 /var/lib/kubelet/pods/{Pod UID}/volumes/kubernetes.io~configmap/extra-cfg/..2020_03_29_03_12_13.444136014/extra.ini//deleted /var/lib/kubelet/pods/{Pod UID}/volume-subpaths/extra-cfg/test/0 rw,relatime shared:99 - ext4 /dev/sda1 rw,data=ordered

Bind Mount

当容器启动时,需要将 /var/lib/kubelet/pods/{Pod UID}/volume-subpaths/extra-cfg/test/0 挂载到容器中。

如果原来的时间戳目录被删除,则 mount 会出错: mount: mount(2) failed: No such file or directory

通过简单的命令模拟这个问题:

1
2
3
4
5
# touch a b c
# mount --bind a b
# rm -f a
# mount --bind b c
mount: mount(2) failed: No such file or directory

可以看到,当 a 删除后,b 挂载点无法再被 mount。所以,当容器异常退出需要重启后,如果 configmap 被更新,原先的时间戳文件被删除,这个 subpath 就无法再被 mount 到容器中。

解决方案

Configmap 变更后 Unmount

社区相关 PR: https://github.com/kubernetes/kubernetes/pull/82784

在容器重启前,检查 subpath 挂载点的源文件和新的目标 subpath 文件是否一致。

configmap 被更新后,时间戳目录变更,则检查到不一致。将 /var/lib/kubelet/pods/{Pod UID}/volume-subpaths/extra-cfg/test/0 Unmount,再重新 Bind Mount 当前最新的时间戳目录下的对应文件。

根据社区 PR 中的 comments 来看,此方案可能存在一定风险,尚不明确(有人指出在 4.18 以下内核是不安全的 链接),所以很长时间都没有进展。

通过一段时间的测试,尚未发现明显的问题。

不使用 subpath

使用其他方式绕过这个问题。

例如可以将 Configmap 整个 Mount 到容器的其他目录下,再在容器启动时通过软链的方式链接到对应的路径下。

为什么使用间接 Bind Mount 而不是直接 Mount 软链接

参考 https://kubernetes.io/blog/2018/04/04/fixing-subpath-volume-vulnerability/ 这篇文章。

可以看出原先使用的就是直接 Mount 软链接的方式,但是存在安全漏洞,symlink race 。恶意程序可以通过构造一个软链接,使特权程序(kubelet) 将超出权限范围之外的文件内容挂载到用户容器中。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
apiVersion: v1
kind: Pod
metadata:
name: my-pod
spec:
initContainers:
- name: prep-symlink
image: "busybox"
command: ["bin/sh", "-ec", "ln -s / /mnt/data/symlink-door"]
volumeMounts:
- name: my-volume
mountPath: /mnt/data
containers:
- name: my-container
image: "busybox"
command: ["/bin/sh", "-ec", "ls /mnt/data; sleep 999999"]
volumeMounts:
- mountPath: /mnt/data
name: my-volume
subPath: symlink-door
volumes:
- name: my-volume
emptyDir: {}

使用如上的配置,通过 emptyDir,在 initContainer 中在挂载的 Volume 目录中创建了一个指向根目录的软链接。

之后正常的容器启动,但是指定了 subpath,如果 kubelet 直接 Mount 软链接,会将宿主机的根目录 Mount 到用户容器中。

为了解决这个问题,需要解析出软链接对应的真实文件路径,并且判断此路径是否是在 Volume 目录下,校验通过后才能挂载到容器中。但是由于校验和挂载之间存在时间差,此文件还是有可能会被篡改。

社区讨论后,通过引入中间 Bind Mount 的机制,相当于给这个文件加锁,将原文件的路径固化,之后再 Mount 到容器中时,只会 Mount 当时创建挂载点时的源文件。

更新

给社区提交的修复 PR 已经被合入 89629

功能总结

导出数据包

方法:File | Export Packet Dissections | as”CSV”(Comma Separated Values packet summary)file…

  1. 导出格式有纯文本、CSV、XML、JSON等;
  2. 不仅可以输出选中列,还可以输出当前页面展示的列,以及所有列(在导出弹框中设置);
  3. 可以设置包格式,比如导出统计行、统计头、包详细数据等;

添加展示列

方法:Package Details 面板中展开包详情,找到指定字段右键单击并选择Apply as Column 选项

显示一个TCP/UDP 会话

方法1:选中一个包,右键选择Conversation Filter|[TCPIUDP]命令

方法2:选中一个包,右键选择Follow[TCPIUDP] Stream 命令

方法3:工具栏选择Statistics|Conversations命令

方法4:在TCP 头部,通过右键单击stream index 字段并选择Apply as Filter 命令

命令总结

捕获过滤命令

捕获过滤器仅支持协议过滤。

1. 主机相关过滤命令*

  • host 10.3.1.1: 捕获到达/来自10.3.1.1主机的数据(支持IPv6地址)。
  • not host 10.3.1.1: 捕获除了到达/来自10.3.1.1主机的所有数据。
  • src host 10.3.1.1: 捕获来自10.3.1.1 主机上的数据。
  • dst host 10.3.1.1: 捕获到达10.3.1.1 主机上的数据。
  • host 10.3.1.1 or host 10.3.1.2: 捕获到达/来自10.3.1.1主机上的数据,和到达/来自10.3.1.2 主机的数据。

2. 端口相关过滤命令*

  • port 53: 捕获到达/来自端口号为53的UDP/TCP 数据(典型的DNS 数据)。
  • not port 53 : 捕获除到达/来自端口号为53的所有UDP/TCP 数据。
  • port 80: 捕获到达/来自端口号为80的UDP/TCP 数据(典型的HTTP 数据)。
  • udp port 67 : 捕获到达/来自端口号为67的UDP 数据(典型的DHCP 数据)。
  • tcp port 21: 捕获到达/来自端口号为21的TCP 数据(典型的FTP 数据)。
  • portrange 1-80: 捕获到达/来自1~80端口号的UDP/TCP 数据。
  • tcp portrange 1-80: 捕获到达/来自1~80端口号的TCP 数据。

3. 主机和端口混合过滤命令*

  • port 20 or port 21 :捕获到达/来自20 或21 端口号的所有UDP/TCP 数据。
  • host 10.3.1.1 and port 80: 捕获到达/来自端口号为80, 并且是到达/来自10.3.1.1主机的UDP/TCP 数据。
  • host 10.3.1.1 and not port 80: 捕获到I来自10.3.1.1 主机,并且是非80 端口的UDP/TCP 数据。
  • udp src port 68 and udp dst port 67: 捕获来自端口为68, 目标端口号为67 的所有UDP 数据(典型的DHCP 客户端到DHCP 服务器的数据) 。
  • udp src port 67 and udp dst port 68: 捕获来自端口号为67, 目标端口号为68 的所有UDP 数据(典型的DHCP 服务器到DHCP 客户端的数据)。

4. IP地址范围过滤命令

  • net 192.168.0.0/24:捕获到达/来自192.168.0.0网络中任何主机的数据。
  • net 192.168.0.0 mask 255.255.255.0: 捕获到达/来自192.168.0.0网络中任何主机的
    数据。
  • ip6 net 2406:daOO:ff00::/64: 捕获到达/来自2406:daOO:ffDO:OOOO ( IPv6) 网络中任
    何主机的数据。
  • not dst net 192.168.0.0/24: 捕获除目的IP地址是192.168.0.0网络外的所有数据。
  • dst net 192.168.0.0/24:捕获到达IP地址为192.168.0.0网络内的所有数据。
  • src net 192.168.0.0/24: 捕获来自IP地址为192.168.0.0网络内的所有数据。

5. 广播或多播地址过滤命令

  • ip broadcast: 捕获到255.255.255.255 的数据。
  • ip multicast: 捕获通过224.0.0.0~239.255.255.255的数据。
  • dst host ff02::1: 捕获所有主机到IPv6多播地址的数据。
  • dst host ff02::2: 捕获所有路由到IPv6多播地址的数据。(跟上一个有什么区别?

6. MAC地址过滤命令

  • ether host 00:08:15:00:08:15: 捕获到达/来自00:08:15:00:08:15主机的数据。
  • ether src 02:0A:42:23:41:AC: 捕获来自02:0A:42:23:41:AC 主机的数据。
  • ether dst 02:0A:42:23:41:AC: 捕获到达02:0A:42:23:41:AC 主机的数据。
  • not ether host 00:08:15:00:08:15:捕获到达/来自除了00:08:15:00:08:15的任何MAC
    地址的流量。

7. 特定ICMP协议过滤命令

  • icmp:捕获所有ICMP 数据包。
  • icmp[0]=8 : 捕获所有ICMP 字段类型为8 (Echo Request) 的数据包。
  • icmp[0]=17: 捕获所有ICMP 字段类型为17 (Address Mask Request) 的数据包。
  • icmp[0]=8 or icmp[0]=0: 捕获所有ICMP 字段类型为8 (Echo Request) 或ICMP
    字段类型为0 (Echo Reply) 的数据包。
  • icmp[0]=3 and not icmp[1]=4 :捕获所有ICMP 字段类型为3 (Destination
    Unreachable) 的包,除了ICMP 字段类型为3/代码为4 (Fragmentation Needed and
    Don’t Fragment was Set) 的数据包。

显示过滤命令

显示过滤器可以帮助用户在捕捉结果中进行数据查找。该过滤器可以在得到的捕捉结果中修改,以显示有用数据。

既支持协议过滤也支持内容过滤。

1. 通用语法格式

1
2
Protocol | [String1] [String2] | Comparison-Operator | Value | Logical-Operations | Other-expression
协议(2~7层) 协议子类 比较运算符 比较值 逻辑运算符 其他表达式

其中比较运算符有如下6个:

英文写法 C 语言写法 含义
eq == 等于
ne != 不等于
gt > 大于
lt < 小于
ge >= 大于等于
le <= 小于等于
contains - 包含
matches - 匹配

逻辑运算符有如下4个:

英文写法 C 语言写法 含义
and && 逻辑与
or || 逻辑或
xor ^^ 逻辑异或
not ! 逻辑非

2. 协议过滤命令*

  • arp: 显示所有ARP 流量,包括免费ARP 、ARP 请求和ARP 应答。
  • ip(v6): 显示所有IPv4/IPv6 流量,包括有IPv4(IPv6) 头部嵌入式的包(如ICMP 目标不可达的数据包,返回到ICMP 头后进入到IPv4 头部)。
    • ip(v6).src
    • ip(v6).dst
    • ip(v6).host
    • ip(v6).addr
  • tcp: 显示所有基于TCP 的流量数据。

3. 应用过滤命令*

  • bootp: 显示所有DHCP 流量(ipv4下基于BOOTP,ipv6下不是基于BOOTP,过滤时使用dhcpv6) 。
  • dns: 显示所有DNS 流量,包括基于TCP 传输和UDP 的DNS 请求和响应。
  • tftp: 显示所有TFTP (简单文件传输协议)流量。
  • http: 显示所有HTTP 命令、响应和数据传输包。但是不显示TCP 握手包、TCP确认包或TCP 断开连接的包。
  • http contains “GET”: 显示HTTP 客户端发送给HTTP 服务器的所有GET 请求数据。
  • icmp: 显示所有ICMP 流量。

4. 字段存在过滤命令

  • bootp.option.hostname: 显示所有DHCP 流量,包含主机名( DHCP 是基于BOOTP) 。
  • http.host: 显示所有包含有HTTP 主机名字段的HTTP 包。该包通常是由客户端发送给一个Web 服务器的请求。
  • ftp.request.command: 显示所有FTP 命令数据,如USER 、PASS 或RETR 命令。
  • ftp.request.arg matches “admin”: 显示匹配admin 字符串的数据。
  • tcp.analysis.flags: 显示所有与TCP 标识相关的包,包括丢包、重发或者零窗口标志。
  • tcp.analysis.zero_window: 显示被标志的包,来表示发送方的缓冲空间已满。

5. 逻辑运算过滤命令

  • &&或and: ip.src=l0.2.2.2 && tcp.port=80,表示显示源地址10.2.2.2 主机,并且端口号为80 的所有IPv4 流量。
  • ||或or: tcp.port=80 || tcp.port=43,表示显示到达/来自80 或443 端口的所有TCP数据。
  • !或not: !arp,表示查看除ARP 外的所有数据。
  • !=或ne: tcp.flags.syn != 1,表示查看TCP SYN 标志位不是1 的TCP 数据帧。

注:

ip.addr != 10.2.2.2 表示显示IP 源或目标地址字段非10.2.2.2 的数据包。如果一个包的源或目标IP 地址字段中不包含10.2.2.2, 则显示该数据包。在该语法中使用了一个隐含或,并且不会过滤掉任何数据包。

!ip.addr == 10.2.2.2 表示显示在IP 源和目标地址字段不包含10.2.2.2 的数据包。当排除到达/来自一个特定IP 地址的数据时,这是一个合适的过滤器语法。

!tcp.flags.syn==l 表示显示TCP SYN 标志位不等于1的所有TCP 包和其他协议包,如UDP 、ARP数据包将匹配该过滤器。因为UDP 和ARP 协议中没有TCP SYN 标志位为1 的数据包。

tcp.flags.syn != 1 表示仅显示包括SYN 设置为0 的TCP 包。

6. 时间过滤命令

  • frame.time_delta > 1,表示时间延迟超过1 秒的数据,显示捕获文件中所有包的时间。
  • tcp.time_delta > 1,表示TCP 时间差大于1 秒的数据。

注:上述命令主要用于判断各种网络延迟。

问题背景

IPv6环境下,在浏览器中通过http://[vip:port]访问web业务,提示无法访问此网站,[vip]的响应时间过长。

分析过程

之前碰到过多次在PC浏览器上无法访问vip的情况,排查方法也很明确:

  1. 在集群的vip所在节点上访问是否正常;
  2. 在集群范围内其他节点上访问是否正常;
  3. 在集群之外的同网段linux环境上访问是否正常;
  4. 在其他环境的PC浏览器上访问是否正常;

验证发现,直接在vip所在节点上访问竟然不通!登录vip所在节点执行ip addr可以看到该地址确实是正确配置了,但 ping6该地址无回应,对应的ipv4地址 ping有回应。按说ping本机的地址不应该和链路的状态有关系,那会是什么原因呢?在仔细检查地址配置情况后发现该地址有个标记tentative dadfailed

1
2
3
4
5
6
7
8
17: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UP group default qlen 1000
link/ether 0c:da:41:1d:a8:62 brd ff:ff:ff:ff:ff:ff
inet 10.10.10.17/16 scope global eth0
valid_lft forever preferred_lft forever
inet6 2000::10:18/128 scope global tentative dadfailed
valid_lft forever preferred_lft 0sec
inet6 fe80::eda:41ff:fe1d:a862/64 scope link
valid_lft forever preferred_lft forever

ip-address(8) 查到对该标记的解释如下:

1
2
tentative
(IPv6 only) only list addresses which have not yet passed duplicate address detection.

显然该地址没有通过地址重复探测(duplicate address detection,简称dad),而且这种检查机制只针对IPv6经确认,该环境的IPv6网段只有自己在用,且未手工配置过IPv6地址,但该环境曾经发生过切主

至此问题基本明确了,切主时会把老的主节点上的vip删除,再到新的主节点上把vip添加上去。如果一切正常,按照这个顺序切主没有问题,但也存在某些异常情况(比如老主上的vip没有及时删掉,而新主上已经添加好了),此时就会触发dad机制。经过验证,一旦出现dadfailed,即使地址冲突解决了,该地址依然无法访问;

解决方案

方案1:在sysctl配置中增加如下内核参数:

1
2
3
4
5
6
7
net.ipv6.conf.all.accept_dad = 0
net.ipv6.conf.default.accept_dad = 0
net.ipv6.conf.eth0.accept_dad = 0

# IPv6 Privacy Extensions (RFC 4941)
net.ipv6.conf.all.use_tempaddr = 0
net.ipv6.conf.default.use_tempaddr = 0

方案2:在ip addr add命令执行时增加nodad标识:

1
ip addr add 2000::10:18/128 dev eth0 nodad

参考资料

  1. https://blog.clanzx.net/network/ipv6-dad.html

问题背景

使用附加网络的Pod在服务器重启后启动异常,报错信息如下:

1
2
3
4
5
6
Events:
Type Reason Age From Message
Normal Scheduled 53m default-scheduler Successfully assigned xxx/xxx1-64784c458b-q67tx to node001
Warning FailedCreatePodSandBox 53m kubelet, node001 Failed to create pod sandbox: rpc er or: code = Unknown desc = failed to set up sandbox container "xxx" network for pod "xxxl-64784c458b-q67tx": NetworkPlugin cni failed to set up pod "xxx1-64784c458b-q67tx_xxx" network: Multus: Err adding pod to network "net-netl-nodeOOl": Multus: error in invoke Delegate add - "macvlan": failed to create macvlan: device or resource busy
Warning FailedCreatePodSandBox 53m kubelet, node001 Failed to create pod sandbox: rpc er or: code = Unknown desc = failed to set up sandbox container "xxx" network for pod "xxxl-64784c458b-q67tx": NetworkPlugin cni failed to set up pod "xxx1-64784c458b-q67tx_xxx" network: Multus: Err adding pod to network "net-netl-nodeOOl": Multus: error in invoke Delegate add - "macvlan": failed to create macvlan: device or resource busy
...

分析过程

从日志初步看,创建Pod的sandbox异常,具体是Multus无法将Pod添加到net-netl-nodeOOl网络命名空间内,再具体点是Multus无法创建macvlan网络,原因是device or resource busy

最后的这个错误信息还是比较常见的,从字面理解,就是设备或资源忙,常见于共享存储的卸载场景。那这里也应该类似,有什么设备或资源处于被占用状态,所以执行macvlan的创建失败,既然是附加网络的问题,那优先查看了下附加网络相关的CRD资源,没什么异常;

网上根据日志搜索一番,也没有什么比较相关的问题,那就看代码吧,首先找到Multus的源码,根据上述日志找相关处理逻辑,没有找到。再一想,Multus实现macvlan网络使用的是macvlan插件,再下载插件代码,找到了相关处理逻辑:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
plugins/main/macvlan/macvlan.go:169
if err := netlink.LinkAdd(mv); err != nil {
return nil, fmt.Errorf("failed to create macvlan: %v", err)
}

// LinkAdd adds a new link device. The type and features of the device
// are taken from the parameters in the link object.
// Equivalent to: `ip link add $link`
func LinkAdd(link Link) error {
return pkgHandle.LinkAdd(link)
}

// LinkAdd adds a new link device. The type and features of the device
// are taken from the parameters in the link object.
// Equivalent to: `ip link add $link`
func (h *Handle) LinkAdd(link Link) error {
return h.linkModify(link, unix.NLM_F_CREATE|unix.NLM_F_EXCL|unix.NLM_F_ACK)
}
...

根据上述代码和注释简单的看,是在执行ip link add $link命令时报错,实际验证看看:

1
2
[root@node001 ~] ip link add link bond1 name macvlan1 type macvlan mode bridge
RTNETLINK answers: Device or resource busy

确实如此,在bond1接口上无法配置macvlan,那换一个接口试试:

1
2
3
4
5
6
[root@node001 ~] ip link add link bond0 name macvlan1 type macvlan mode bridge
[root@node001 ~] ip link show
...
110: macvlan1@bond0: <BROADCAST,MULTICAST> mtu 1500 qdisc noop state DOWN mode DEFAULT group default qlen 1000
link/ether ea:31:c9:7f:d9:a4 brd ff:ff:ff:ff:ff:ff
...

配置成功,说明bond1接口有什么问题,看看这俩接口有没有差异:

1
2
3
4
5
6
7
8
9
10
11
12
[root@node001 ~] ip addr show
...
2: bond0: <BROADCAST,MULTICAST,MASTER,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
link/ether 0c:da:41:1d:6f:ca brd ff:ff:ff:ff:ff:ff
inet x.x.x.x/16 brd x.x.255.255 scope global bond0
valid_lft forever preferred_lft forever
inet6 fe80::eda:41ff:fe1d:6fca/64 scope link
valid_lft forever preferred_lft forever
...
17: bond1: <BROADCAST,MULTICAST,MASTER,SLAVE,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP group default qlen 1000
link/ether 0c:da:41:1d:a8:62 brd ff:ff:ff:ff:ff:ff
...

对比两个接口可以发现两个差异点:

  1. bond0配置了IP地址,而bond1没有配置;
  2. bond0是MASTER角色,bond1既是MASTER,又是SLAVE角色;

考虑到bond0接口是用来建集群的,bond1接口是给Multus创建macvlan网络用的,所以第一个差异点属于正常现象。第二个是什么情况呢?一般来说,配置bond的目的是把几个物理接口作为SLAVE角色聚合成bond接口,这样既能增加服务器的可靠性,又增加了可用网络宽带,为用户提供不间断的网络服务。配置后,实际的物理接口应该是SLAVE角色,而聚合后的bond接口应该是MASTER角色,所以正常来说,不会同时出现两个角色才对;

查看两个bond的相关配置,没有发现什么异常,反过来讲,如果配置的有问题,那初次部署就应该报错了,而不是重启节点才发现。所以,问题的关键是重启导致的。也就是说,可能是在重启后的启动脚本里加了什么配置影响的;

搜索相关资料[1],发现在配置过程中可能有这么一个操作:

1
2
4、在/etc/rc.d/rc.local文件中加入如下语句,使系统启动自动运行
ifenslave bond0 eth0 eth1

查看问题环境上怎么配置的:

1
2
3
4
[root@node001 ~] cat /etc/rc.local
...
touch /var/lock/subsys/local
ifenslave bond0 bond1 enp661s0f0 enp661s0f1 ens1f0 ens1f1

发现有类似的配置,但不同的是,问题环境上配置了两个bond,并且配置在了一个命令里。感觉不是太对,个人理解这么配置应该会把bond1也认为是bond0的SLAVE,修改一下试试:

1
2
3
4
5
6
[root@node001 ~] cat /etc/rc.local
...
touch /var/lock/subsys/local
ifenslave bond0 enp661s0f0 enp661s0f1
ifenslave bond1 ens1f0 ens1f1
[root@node001 ~] systemctl restart network

再观察两个bond接口的角色,发现恢复正常,再看看异常Pod,也都起来了。

1
2
[root@node001 ~] kubectl get pod -A |grep -v Running
NAMESPACE NAME READY STATUS RESTARTS AGE

解决方案

rc.local里的两个bond的命令拆开分别配置即可。

参考资料

  1. https://www.cnblogs.com/geaozhang/p/6763876.html

问题背景

通过kubectl delete命令删除某个业务Pod后,该Pod一直处于Terminating状态。

原因分析

根据现象看,应该是删除过程中有哪个流程异常,导致最终的删除卡在了Terminating状态。先describe看一下:

1
2
[root@node1 ~]# kubectl describe pod -n xxx cam1-78b6fc6bc8-cjsw5
// 没有发现什么异常信息,这里就不贴日志了

Event事件中未见明显异常,那就看负责删除Pod的kubelet组件日志(已过滤出关键性日志):

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
I0728 16:24:57.339295    9744 kubelet.go:1904] SyncLoop (DELETE, "api"): "cam1-78b6fc6bc8-cjsw5_cam(5c948341-c030-4996-b888-f032577d97b0)"
I0728 16:24:57.339720 9744 kuberuntime_container.go:581] Killing container "docker://a73082a4a9a4cec174bb0d1c256cc11d804d93137551b9bfd3e6fa1522e98589" with 60 second grace period
I0728 16:25:18.259418 9744 kubelet.go:1904] SyncLoop (DELETE, "api"): "cam1-78b6fc6bc8-cjsw5_cam(5c948341-c030-4996-b888-f032577d97b0)"
2021-07-28 16:25:19.247 [INFO][394011] ipam.go 1173: Releasing all IPs with handle 'cam.cam1-78b6fc6bc8-cjsw5'
2021-07-28 16:25:19.254 [INFO][393585] k8s.go 498: Teardown processing complete.

// 可疑点1:没有获取到pod IP
W0728 16:25:19.303513 9744 docker_sandbox.go:384] failed to read pod IP from plugin/docker: NetworkPlugin cni failed on the status hook for pod "cam1-78b6fc6bc8-cjsw5_cam": Unexpected command output Device "eth0" does not exist.
with error: exit status 1

I0728 16:25:19.341068 9744 kubelet.go:1933] SyncLoop (PLEG): "cam1-78b6fc6bc8-cjsw5_cam(5c948341-c030-4996-b888-f032577d97b0)", event: &pleg.PodLifecycleEvent{ID:"5c948341-c030-4996-b888-f032577d97b0", Type:"ContainerDied", Data:"a73082a4a9a4cec174bb0d1c256cc11d804d93137551b9bfd3e6fa1522e98589"}
I0728 16:25:20.578095 9744 kubelet.go:1933] SyncLoop (PLEG): "cam1-78b6fc6bc8-cjsw5_cam(5c948341-c030-4996-b888-f032577d97b0)", event: &pleg.PodLifecycleEvent{ID:"5c948341-c030-4996-b888-f032577d97b0", Type:"ContainerDied", Data:"c3b992465cd2085300995066526a36665664558446ff6e1756135c3a5b6df2e6"}

I0728 16:25:20.711967 9744 kubelet_pods.go:1090] Killing unwanted pod "cam1-78b6fc6bc8-cjsw5"

// 可疑点2:Unmount失败
E0728 16:25:20.939400 9744 nestedpendingoperations.go:301] Operation for "{volumeName:kubernetes.io/glusterfs/5c948341-c030-4996-b888-f032577d97b0-cam-pv-50g podName:5c948341-c030-4996-b888-f032577d97b0 nodeName:}" failed. No retries permitted until 2021-07-28 16:25:21.439325811 +0800 CST m=+199182.605079651 (durationBeforeRetry 500ms). Error: "UnmountVolume.TearDown failed for volume \"diag-log\" (UniqueName: \"kubernetes.io/glusterfs/5c948341-c030-4996-b888-f032577d97b0-cam-pv-50g\") pod \"5c948341-c030-4996-b888-f032577d97b0\" (UID: \"5c948341-c030-4996-b888-f032577d97b0\") : Unmount failed: exit status 32\nUnmounting arguments: /var/lib/kubelet/pods/5c948341-c030-4996-b888-f032577d97b0/volumes/kubernetes.io~glusterfs/cam-pv-50g\nOutput: umount: /var/lib/kubelet/pods/5c948341-c030-4996-b888-f032577d97b0/volumes/kubernetes.io~glusterfs/cam-pv-50g:目标忙。\n (有些情况下通过 lsof(8) 或 fuser(1) 可以\n 找到有关使用该设备的进程的有用信息。)\n\n"

从删除Pod的日志看,有2个可疑点:

  1. docker_sandbox.go:384打印的获取pod IP错误;
  2. nestedpendingoperations.go:301打印的Unmount失败错误;

先看第1点,根据日志定位到代码[1]位置如下,IP没有拿到所以打印了个告警并返回空IP地址;

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
pkg/kubelet/dockershim/docker_sandbox.go:348
func (ds *dockerService) getIP(podSandboxID string, sandbox *dockertypes.ContainerJSON) string {
if sandbox.NetworkSettings == nil {
return ""
}
if networkNamespaceMode(sandbox) == runtimeapi.NamespaceMode_NODE {
// For sandboxes using host network, the shim is not responsible for
// reporting the IP.
return ""
}

// Don't bother getting IP if the pod is known and networking isn't ready
ready, ok := ds.getNetworkReady(podSandboxID)
if ok && !ready {
return ""
}

ip, err := ds.getIPFromPlugin(sandbox)
if err == nil {
return ip
}

if sandbox.NetworkSettings.IPAddress != "" {
return sandbox.NetworkSettings.IPAddress
}
if sandbox.NetworkSettings.GlobalIPv6Address != "" {
return sandbox.NetworkSettings.GlobalIPv6Address
}

// 错误日志在这里
klog.Warningf("failed to read pod IP from plugin/docker: %v", err)
return ""
}

继续看getIP方法的调用处代码,这里如果没有拿到IP,也没有什么异常,直接把空值放到PodSandboxStatusResponse中并返回;

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
pkg/kubelet/dockershim/docker_sandbox.go:404
func (ds *dockerService) PodSandboxStatus(ctx context.Context, req *runtimeapi.PodSandboxStatusRequest) (*runtimeapi.PodSandboxStatusResponse, error) {
podSandboxID := req.PodSandboxId

r, metadata, err := ds.getPodSandboxDetails(podSandboxID)
if err != nil {
return nil, err
}

// Parse the timestamps.
createdAt, _, _, err := getContainerTimestamps(r)
if err != nil {
return nil, fmt.Errorf("failed to parse timestamp for container %q: %v", podSandboxID, err)
}
ct := createdAt.UnixNano()

// Translate container to sandbox state.
state := runtimeapi.PodSandboxState_SANDBOX_NOTREADY
if r.State.Running {
state = runtimeapi.PodSandboxState_SANDBOX_READY
}

// 调用getIP方法的位置
var IP string
if IP = ds.determinePodIPBySandboxID(podSandboxID); IP == "" {
IP = ds.getIP(podSandboxID, r)
}

labels, annotations := extractLabels(r.Config.Labels)
status := &runtimeapi.PodSandboxStatus{
Id: r.ID,
State: state,
CreatedAt: ct,
Metadata: metadata,
Labels: labels,
Annotations: annotations,
Network: &runtimeapi.PodSandboxNetworkStatus{
Ip: IP,
},
Linux: &runtimeapi.LinuxPodSandboxStatus{
Namespaces: &runtimeapi.Namespace{
Options: &runtimeapi.NamespaceOption{
Network: networkNamespaceMode(r),
Pid: pidNamespaceMode(r),
Ipc: ipcNamespaceMode(r),
},
},
},
}
return &runtimeapi.PodSandboxStatusResponse{Status: status}, nil
}

到此看不出这个错误会不会中断删除流程,那就本地构造一下试试。修改上面的代码,在调用getIP方法的位置后面增加调试日志(从本地验证结果看,Pod正常删除,说明异常问题与此处无关);

1
2
3
4
5
6
7
8
9
10
11
// 调用getIP方法的位置
var IP string
if IP = ds.determinePodIPBySandboxID(podSandboxID); IP == "" {
IP = ds.getIP(podSandboxID, r)
}

// 新加调试日志,如果是指定的Pod,强制将IP置空
isTestPod := strings.Contains(metadata.GetName(), "testpod")
if isTestPod {
IP = ""
}

再看第2点,这个是ERROR级别的错误,问题出在Unmount挂载点时失败。那么卸载挂载点失败会导致卸载流程提前终止吗?网上关于Pod删除流程的源码分析文章很多,我们就直接找几篇[2,3,4]看看能不能解答上面的问题。

简单总结来说,删除一个Pod的流程如下:

  1. 调用kube-apiserverDELETE接口(默认带grace-period=30s);
  2. 第一次的删除只是更新Pod对象的元信息(DeletionTimestamp字段和DeletionGracePeriodSeconds字段),并没有在Etcd中删除记录;
  3. kubectl命令的执行会阻塞并显示正在删除Pod;
  4. kubelet组件监听到Pod对象的更新事件,执行killPod()方法;
  5. kubelet组件监听到pod的删除事件,第二次调用kube-apiserverDELETE接口(带grace-period=0
  6. kube-apiserverDELETE接口去etcd中删除Pod对象;
  7. kubectl命令的执行返回,删除Pod成功;

从前面kubelet删除异常的日志看,确实有两次DELETE操作,并且中间有个Killing container的日志,但从上面的删除流程看,两次DELETE操作之间应该是调用killPod()方法,通过查看源码,对应的日志应该是Killing unwanted pod,所以,实际上第二次的DELETE操作并没有触发。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
pkg/kubelet/kubelet_pods.go:1073
func (kl *Kubelet) podKiller() {
killing := sets.NewString()
// guard for the killing set
lock := sync.Mutex{}
for podPair := range kl.podKillingCh {
runningPod := podPair.RunningPod
apiPod := podPair.APIPod

lock.Lock()
exists := killing.Has(string(runningPod.ID))
if !exists {
killing.Insert(string(runningPod.ID))
}
lock.Unlock()

// 这里在调用killPod方法前会打印v2级别的日志
if !exists {
go func(apiPod *v1.Pod, runningPod *kubecontainer.Pod) {
klog.V(2).Infof("Killing unwanted pod %q", runningPod.Name)
err := kl.killPod(apiPod, runningPod, nil, nil)
if err != nil {
klog.Errorf("Failed killing the pod %q: %v", runningPod.Name, err)
}
lock.Lock()
killing.Delete(string(runningPod.ID))
lock.Unlock()
}(apiPod, runningPod)
}
}
}

怎么确认第二次的DELETE操作有没有触发呢?很简单,看代码或者实际验证都可以。这里我就在测试环境删除个Pod看下相关日志:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
[root@node2 ~]# kubectl delete pod -n xxx  testpodrc2-7b749f6c9c-qh68l
pod "testpodrc2-7b749f6c9c-qh68l" deleted

// 已过滤出关键性日志
[root@node2 ~]# tailf kubelet.log
I0730 13:27:31.854178 24588 kubelet.go:1904] SyncLoop (DELETE, "api"): "testpodrc2-7b749f6c9c-qh68l_testpod(85ee282f-a843-4f10-a99c-79d447f83f2a)"
I0730 13:27:31.854511 24588 kuberuntime_container.go:581] Killing container "docker://e2a1cd5f2165e12cf0b46e12f9cd4d656d593f75e85c0de058e0a2f376a5557e" with 30 second grace period
I0730 13:27:32.203167 24588 kubelet.go:1904] SyncLoop (DELETE, "api"): "testpodrc2-7b749f6c9c-qh68l_testpod(85ee282f-a843-4f10-a99c-79d447f83f2a)"

I0730 13:27:32.993294 24588 kubelet.go:1933] SyncLoop (PLEG): "testpodrc2-7b749f6c9c-qh68l_testpod(85ee282f-a843-4f10-a99c-79d447f83f2a)", event: &pleg.PodLifecycleEvent{ID:"85ee282f-a843-4f10-a99c-79d447f83f2a", Type:"ContainerDied", Data:"e2a1cd5f2165e12cf0b46e12f9cd4d656d593f75e85c0de058e0a2f376a5557e"}
I0730 13:27:32.993428 24588 kubelet.go:1933] SyncLoop (PLEG): "testpodrc2-7b749f6c9c-qh68l_testpod(85ee282f-a843-4f10-a99c-79d447f83f2a)", event: &pleg.PodLifecycleEvent{ID:"85ee282f-a843-4f10-a99c-79d447f83f2a", Type:"ContainerDied", Data:"c6a587614976beed0cbb6e5fabf70a2d039eec6c160154fce007fe2bb1ba3b4f"}

I0730 13:27:34.072494 24588 kubelet_pods.go:1090] Killing unwanted pod "testpodrc2-7b749f6c9c-qh68l"

I0730 13:27:40.084182 24588 kubelet.go:1904] SyncLoop (DELETE, "api"): "testpodrc2-7b749f6c9c-qh68l_testpod(85ee282f-a843-4f10-a99c-79d447f83f2a)"
I0730 13:27:40.085735 24588 kubelet.go:1898] SyncLoop (REMOVE, "api"): "testpodrc2-7b749f6c9c-qh68l_testpod(85ee282f-a843-4f10-a99c-79d447f83f2a)"

对比正常和异常场景下的日志可以看出,正常的删除操作下,Killing unwanted pod日志之后会有DELETEREMOVE的操作,这也就说明问题出在第二次DELETE操作没有触发。查看相关代码:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
pkg/kubelet/status/status_manager.go:470
//kubelet组件有一个statusManager模块,它会for循环调用syncPod()方法
//方法内部有机会调用kube-apiserver的DELETE接口(强制删除,非平滑)
func (m *manager) syncPod(uid types.UID, status versionedPodStatus) {
...

//当pod带有DeletionTimestamp字段,并且其内容器已被删除、持久卷已被删除等的多条件下,才会进入if语句内部
if m.canBeDeleted(pod, status.status) {
deleteOptions := metav1.NewDeleteOptions(0)
deleteOptions.Preconditions = metav1.NewUIDPreconditions(string(pod.UID))

//强制删除pod对象:kubectl delete pod podA --grace-period=0
err = m.kubeClient.CoreV1().Pods(pod.Namespace).Delete(pod.Name, deleteOptions)
...

}
}

从源码可以看出,第二次DELETE操作是否触发依赖于canBeDeleted方法的校验结果,而这个方法内会检查持久卷是否已经被删除:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
pkg/kubelet/status/status_manager.go:538
func (m *manager) canBeDeleted(pod *v1.Pod, status v1.PodStatus) bool {
if pod.DeletionTimestamp == nil || kubepod.IsMirrorPod(pod) {
return false
}
return m.podDeletionSafety.PodResourcesAreReclaimed(pod, status)
}

pkg/kubelet/kubelet_pods.go:900
func (kl *Kubelet) PodResourcesAreReclaimed(pod *v1.Pod, status v1.PodStatus) bool {
...

// 这里会判断挂载卷是否已卸载
if kl.podVolumesExist(pod.UID) && !kl.keepTerminatedPodVolumes {
// We shouldnt delete pods whose volumes have not been cleaned up if we are not keeping terminated pod volumes
klog.V(3).Infof("Pod %q is terminated, but some volumes have not been cleaned up", format.Pod(pod))
return false
}
if kl.kubeletConfiguration.CgroupsPerQOS {
pcm := kl.containerManager.NewPodContainerManager()
if pcm.Exists(pod) {
klog.V(3).Infof("Pod %q is terminated, but pod cgroup sandbox has not been cleaned up", format.Pod(pod))
return false
}
}
return true
}

结合出问题的日志,基本能确认是Unmount挂载点失败导致的异常。那么,挂载点为啥会Unmount失败?

1
2
// umount失败关键日志
Unmount failed: exit status 32\nUnmounting arguments: /var/lib/kubelet/pods/xxx/volumes/kubernetes.io~glusterfs/cam-pv-50g\nOutput: umount: /var/lib/kubelet/pods/xxx/volumes/kubernetes.io~glusterfs/cam-pv-50g:目标忙。\n (有些情况下通过 lsof(8) 或 fuser(1) 可以\n 找到有关使用该设备的进程的有用信息。)\n\n"

仔细看卸载失败的日志,可以看到这个挂载点的后端存储是glusterfs,而目标忙一般来说是存储设备侧在使用,所以无法卸载。那就找找看是不是哪个进程使用了这个挂载目录(以下定位由负责glusterfs的同事提供):

1
2
3
4
[root@node1 ~]# fuser -mv /var/lib/kubelet/pods/xxx/volumes/kubernetes.io~glusterfs/cam-pv-50g
用户 进程号 权限 命令
root kernel mount /var/lib/kubelet/pods/xxx/volumes/kubernetes.io~glusterfs/cam-dialog-gl.uster-pv-50g
root 94549 f.... glusterfs

除了内核的mount,还有个pid=94549glusterfs进程在占用挂载点所在目录,看看是什么进程:

1
2
[root@node1 ~]# ps -ef| grep 94549
root 94549 1 0 7月26 ? 00:01:13 /usr/sbin/glusterfs --log-level=ERR0R --log-file=/var/lib/kubelet/plugins/kubernetes.io/glusterfs/global-diaglog-pv/web-fddf96444-stxpf-glusterfs.log --fuse-mountopts=auto_unmount --process-name fuse --volfile-server=xxx --volfile-server=xxx --tfolfile-server=xxx --volfile-id=global-diaglog --fuse-mountopts=auto_unmount /var/lib/kubelet/pods/xxx/volumes/kubernetef.io-glusterfs/global-diaglog-pv

发现这个进程维护的是web-xxx的挂载信息,而web-xxxcam-xxx没有任何关联。由此推断出是glusterfs管理的挂载信息发送错乱导致,具体错乱原因就转给相关负责的同事看了。

解决方案

从分析结果看,是共享存储卷未正常卸载导致的删除Pod异常,非K8S问题。

参考资料

  1. Kubernetes v1.15.12源码
  2. kubernetes删除pod的流程的源码简析
  3. Kubernetes源码分析之Pod的删除
  4. kubernetes grace period 失效问题排查

问题背景

部署在服务器上的Web应用因为机房迁移,导致PC上无法正常访问Web页面。

原因分析

本次遇到的问题纯属网络层面问题,不用多想,先登录到服务器上,查看服务端口的监听状态:

1
2
[root@node2]# netstat -anp|grep 443
tcp6 0 0 :::443 :::* LISTEN 8450/java

在服务器所在节点、服务器之前的其他节点上curl监听端口看看是否有响应:

1
2
3
4
5
6
7
8
9
[root@node2]# curl -i -k https://192.168.10.10:443
HTTP/1.1 302 Found
Location: https://127.0.0.1:443
Content-Length: 0

[root@node2]# curl -i -k https://192.168.10.11:443
HTTP/1.1 302 Found
Location: https://192.168.10.11:443
Content-Length: 0

到此为止,说明Web服务运行正常,问题出在了PC到服务器这个通信过程。本地wireshark抓包看看,相关异常报文如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
371 70.961626   3.2.253.177     172.30.31.151   TCP     66  52541 → 443 [SYN] Seq=0 Win=8192 Len=0 MSS=1460 WS=4 SACK_PERM=1
373 70.962516 172.30.31.151 3.2.253.177 TCP 66 443 → 52541 [SYN, ACK] Seq=0 Ack=1 Win=29200 Len=0 MSS=1460 SACK_PERM=1 WS=128
375 70.962563 3.2.253.177 172.30.31.151 TCP 54 52541 → 443 [ACK] Seq=1 Ack=1 Win=65700 Len=0
377 70.963248 3.2.253.177 172.30.31.151 TLSv1.2 571 Client Hello
379 70.964323 172.30.31.151 3.2.253.177 TCP 60 443 → 52541 [ACK] Seq=1 Ack=518 Win=30336 Len=0
381 70.965327 172.30.31.151 3.2.253.177 TLSv1.2 144 Server Hello
383 70.965327 172.30.31.151 3.2.253.177 TLSv1.2 105 Change Cipher Spec, Encrypted Handshake Message
385 70.965364 3.2.253.177 172.30.31.151 TCP 54 52541 → 443 [ACK] Seq=518 Ack=142 Win=65556 Len=0
387 70.967194 3.2.253.177 172.30.31.151 TLSv1.2 61 Alert (Level: Fatal, Description: Certificate Unknown)
388 70.967233 3.2.253.177 172.30.31.151 TCP 54 52541 → 443 [FIN, ACK] Seq=525 Ack=142 Win=65556 Len=0
391 70.968320 172.30.31.151 3.2.253.177 TLSv1.2 85 Encrypted Alert
392 70.968321 172.30.31.151 3.2.253.177 TCP 60 443 → 52541 [FIN, ACK] Seq=173 Ack=526 Win=30336 Len=0
394 70.968356 3.2.253.177 172.30.31.151 TCP 54 52541 → 443 [RST, ACK] Seq=526 Ack=173 Win=0 Len=0
395 70.968370 3.2.253.177 172.30.31.151 TCP 54 52541 → 443 [RST] Seq=526 Win=0 Len=0

关键是最后两个,可以看出报文存在复位标志RST。与提供环境的人了解到PC与服务器之间使用的交换机是通过GRE隧道打通的网络,基本怀疑是交换机配置存在问题;

同时观察到PC访问集群的ftp也存在异常,说明是一个通用问题,而PC上pingssh服务器都没有问题,说明是配置导致的部分协议的连接问题;

后来提供环境的人排查交换机配置,发现GRE隧道的默认MTU1464,而集群网卡上的MTU1500,最后协商出的MSS1460(见抓包中的前两个报文):

1
2
3
4
5
6
7
8
9
10
11
12
13
[leaf11]dis interface Tunnel
Tunnel0
Current state: UP
Line protocol state: UP
Description: Tunnel0 Interface
Bandwidth: 64 kbps
Maximum transmission unit: 1464
Internet protocol processing: Disabled
Last clearing of counters: Never
Tunnel source 3.1.1.11, destination 2.1.1.222
Tunnel protocol/transport UDP_VXLAN/IP
Last 300 seconds input rate: 0 bytes/sec, 0 bits/sec, 0 packets/sec
Last 300 seconds output rate: 0 bytes/sec, 0 bits/

这种情况下,最大的报文发到交换机后,因为交换机允许的最大报文数为1464-40=1424字节,所以出现了上述现象,同时也解释了httpftp有问题(长报文),而pingssh没有问题(短报文)。

解决方案

方案1:修改隧道口和物理口的MTU值,但是取值不好定,因为不知道应用最长报文的长度。
方案2:GRE隧道口配置TCPMSS,超出后分片处理。

设置TCPMSS参考命令:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
【命令】
tcp mss value
undo tcp mss
【缺省情况】
未配置接口的TCP最大报文段长度。
【视图】
接口视图
【缺省用户角色】
network-admin
mdc-admin
【参数】
value:TCP最大报文段长度,取值范围为128~(接口的最大MTU值-40),单位为字节。
【使用指导】
TCP最大报文段长度(Max Segment Size,MSS)表示TCP连接的对端发往本端的最大TCP报文段的长度,目前作为TCP连接建立时的一个选项来协商:当一个TCP连接建立时,连接的双方要将MSS作为TCP报文的一个选项通告给对端,对端会记录下这个MSS值,后续在发送TCP报文时,会限制TCP报文的大小不超过该MSS值。当对端发送的TCP报文的长度小于本端的TCP最大报文段长度时,TCP报文不需要分段;否则,对端需要对TCP报文按照最大报文段长度进行分段处理后再发给本端。
该配置仅对新建的TCP连接生效,对于配置前已建立的TCP连接不生效。
该配置仅对IP报文生效,当接口上配置了MPLS功能后,不建议再配置本功能。

参考资料

  1. https://blog.csdn.net/qq_43684922/article/details/105300934

问题背景

如下所示,用户使用kubectl top命令看到其中一个节点上的Harbor占用内存约3.7G(其他业务Pod也存在类似现象),整体上来说,有点偏高。

1
2
3
4
5
6
7
8
9
10
[root@node02 ~]# kubectl get node -owide
NAME STATUS ROLES AGE VERSION INTERNAL-IP EXTERNAL-IP
node01 Ready master 10d v1.15.12 100.1.0.10 <none>
node02 Ready master 12d v1.15.12 100.1.0.11 <none>
node03 Ready master 10d v1.15.12 100.1.0.12 <none>

[root@node02 ~]# kubectl top pod -A |grep harbor
kube-system harbor-master1-sxg2l 15m 150Mi
kube-system harbor-master2-ncvb8 8m 3781Mi
kube-system harbor-master3-2gdsn 14m 227Mi

原因分析

我们知道,查看容器的内存占用,可以使用kubectl top命令,也可以使用docker stats命令,并且理论上来说,docker stats命令查的结果应该比kubectl top查到的更准确。查看并统计发现,实际上Harbor总内存占用约为140M左右,远没有达到3.7G:

1
2
3
4
5
6
7
8
9
10
[root@node02 ~]# docker stats |grep harbor
CONTAINER ID NAME CPU % MEM USAGE / LIMIT MEM %
10a230bee3c7 k8s_nginx_harbor-master2-xxx 0.02% 14.15MiB / 94.26GiB 0.01%
6ba14a04fd77 k8s_harbor-portal_harbor-master2-xxx 0.01% 13.73MiB / 94.26GiB 0.01%
324413da20a9 k8s_harbor-jobservice_harbor-master2-xxx 0.11% 21.54MiB / 94.26GiB 0.02%
d880b61cf4cb k8s_harbor-core_harbor-master2-xxx 0.12% 33.2MiB / 94.26GiB 0.03%
186c064d0930 k8s_harbor-registryctl_harbor-master2-xxx 0.01% 8.34MiB / 94.26GiB 0.01%
52a50204a962 k8s_harbor-registry_harbor-master2-xxx 0.06% 29.99MiB / 94.26GiB 0.03%
86031ddd0314 k8s_harbor-redis_harbor-master2-xxx 0.14% 11.51MiB / 94.26GiB 0.01%
6366207680f2 k8s_harbor-database_harbor-master2-xxx 0.45% 8.859MiB / 94.26GiB 0.01%

这是什么情况?两个命令查到的结果差距也太大了。查看资料[1]可以知道:

  1. kubectl top命令的计算公式:memory.usage_in_bytes - inactive_file
  2. docker stats命令的计算公式:memory.usage_in_bytes - cache

可以看出,两种方式收集机制不一样,如果cache比较大,kubectl top命令看到的结果会偏高。根据上面的计算公式验证看看是否正确:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
curl -s --unix-socket /var/run/docker.sock http:/v1.24/containers/xxx/stats | jq ."memory_stats"
"memory_stats": {
"usage": 14913536,
"max_usage": 15183872,
"stats": {
"active_anon": 14835712,
"active_file": 0,
"cache": 77824,
"dirty": 0,
"hierarchical_memory_limit": 101205622784,
"hierarchical_memsw_limit": 9223372036854772000,
"inactive_anon": 4096,
"inactive_file": 73728,
...
}

"memory_stats": {
"usage": 14405632,
"max_usage": 14508032,
"stats": {
"active_anon": 14397440,
"active_file": 0,
"cache": 8192,
"dirty": 0,
"hierarchical_memory_limit": 101205622784,
"hierarchical_memsw_limit": 9223372036854772000,
"inactive_anon": 4096,
"inactive_file": 4096,
...
}

"memory_stats": {
"usage": 26644480,
"max_usage": 31801344,
"stats": {
"active_anon": 22810624,
"active_file": 790528,
"cache": 3833856,
"dirty": 0,
"hierarchical_memory_limit": 101205622784,
"hierarchical_memsw_limit": 9223372036854772000,
"inactive_anon": 0,
"inactive_file": 3043328,
...
}

"memory_stats": {
"usage": 40153088,
"max_usage": 90615808,
"stats": {
"active_anon": 35123200,
"active_file": 1372160,
"cache": 5029888,
"dirty": 0,
"hierarchical_memory_limit": 101205622784,
"hierarchical_memsw_limit": 9223372036854772000,
"inactive_anon": 0,
"inactive_file": 3657728,
...
}

"memory_stats": {
"usage": 10342400,
"max_usage": 12390400,
"stats": {
"active_anon": 8704000,
"active_file": 241664,
"cache": 1638400,
"dirty": 0,
"hierarchical_memory_limit": 101205622784,
"hierarchical_memsw_limit": 9223372036854772000,
"inactive_anon": 0,
"inactive_file": 1396736,
...
}

"memory_stats": {
"usage": 5845127168,
"max_usage": 22050988032,
"stats": {
"active_anon": 31576064,
"active_file": 3778052096,
"cache": 5813551104,
"dirty": 0,
"hierarchical_memory_limit": 101205622784,
"hierarchical_memsw_limit": 9223372036854772000,
"inactive_anon": 0,
"inactive_file": 2035499008,
...
}

"memory_stats": {
"usage": 13250560,
"max_usage": 34791424,
"stats": {
"active_anon": 12070912,
"active_file": 45056,
"cache": 1179648,
"dirty": 0,
"hierarchical_memory_limit": 101205622784,
"hierarchical_memsw_limit": 9223372036854772000,
"inactive_anon": 0,
"inactive_file": 1134592,
...
}

"memory_stats": {
"usage": 50724864,
"max_usage": 124682240,
"stats": {
"active_anon": 23502848,
"active_file": 13864960,
"cache": 41435136,
"dirty": 0,
"hierarchical_memory_limit": 101205622784,
"hierarchical_memsw_limit": 9223372036854772000,
"inactive_anon": 6836224,
"inactive_file": 6520832,
...
}

根据上面提供的计算公式和实际获取的memory_stats数据,验证kubectl top结果和docker stats结果符合预期。那为什么Harbor缓存会占用那么高呢?

通过实际环境分析看,Harbor中占用缓存较高的组件是registry(如下所示,缓存有5.4G),考虑到registry负责docker镜像的存储,在处理镜像时会有大量的镜像层文件的读写操作,所以正常情况下这些操作确实会比较耗缓存;

1
2
3
4
5
6
7
8
9
10
11
12
13
14
"memory_stats": {
"usage": 5845127168,
"max_usage": 22050988032,
"stats": {
"active_anon": 31576064,
"active_file": 3778052096,
"cache": 5813551104,
"dirty": 0,
"hierarchical_memory_limit": 101205622784,
"hierarchical_memsw_limit": 9223372036854772000,
"inactive_anon": 0,
"inactive_file": 2035499008,
...
}

解决方案

与用户沟通,说明kubectl top看到的结果包含了容器内使用的cache,结果会偏高,这部分缓存在内存紧张情况下会被系统回收,或者手工操作也可以释放,建议使用docker stats命令查看实际内存使用率。

参考资料

  1. https://blog.csdn.net/xyclianying/article/details/108513122

问题背景

接上次的问题,一段时间后,环境再次出现harborcalico因为健康检查不过反复重启的问题,并且使用kubectl命令进入Pod也响应非常慢甚至超时。

1
2
[root@node01 ~]# kubectl exec -it -n system node1-59c9475bc6-zkhq5 bash
^

原因分析

反复重启的原因上次已定位,这次上环境简单看还是因为健康检查超时的问题,并且现象也一样,TCP的连接卡在了第一次握手的SYN_SENT阶段。

1
2
3
[root@node01 ~]# netstat -anp|grep 23380
tcp 0 0 127.0.0.1:23380 0.0.0.0:* LISTEN 38914/kubelet
tcp 0 0 127.0.0.1:38983 127.0.0.1:23380 SYN_SENT -

也就是说,除了TCP连接队列的问题,还存在其他问题会导致该现象。先看看上次的参数还在不在:

1
2
3
[root@node01 ~]# cat /etc/sysctl.conf
net.ipv4.tcp_max_syn_backlog = 32768
net.core.somaxconn = 32768

再看下上次修改的参数是否生效:

1
2
3
[root@node01 ~]# ss -lnt
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 32768 127.0.0.1:23380 *:*

参数的修改也生效了,那为什么还会卡在SYN_SENT阶段呢?从现有情况,看不出还有什么原因会导致该问题,只能摸索看看。

  1. 在问题节点和非问题节点上分别抓包,看报文交互是否存在什么异常;
  2. 根据参考资料[1],排查是否为相同问题;
  3. 根据参考资料[2],排查是否相同问题;

摸索一番,没发现什么异常。回过头来想想,既然是业务下发大量配置导致的,并且影响是全局的(除了业务Pod自身,其他组件也受到了影响),说明大概率原因还是系统层面存在的性能瓶颈。业务量大的影响除了CPU、一般还有内存、磁盘、连接数等等,与开发人员确认他们的连接还是长连接,那么连接数很大的情况下会受到什么内核参数的影响呢?其中一个就是我们熟知的文件句柄数。

1
2
3
4
5
[root@node01 ~]# lsof -p 45775 | wc -l
17974

[root@node01 ~]# lsof -p 45775|grep "sock"| wc -l
12051

嗯,打开了1w+的文件句柄数并且基本都是sock连接,而我们使用的操作系统默认情况下每个进程的文件句柄数限制为1024,查看确认一下:

1
2
[root@node01 ~]# ulimit  -n
1024

超额使用了这么多,业务Pod竟然没有too many open files错误:

1
2
3
[root@node01 ~]# kubectl logs -n system node1-59c9475bc6-zkhq5
start config
...

临时修改一下:

1
2
3
[root@node01 ~]# ulimit -n 65535
[root@node01 ~]# ulimit -n
65535

再次使用kubectl命令进入业务Pod,响应恢复正常,并且查看连接也不再有卡住的SYN_SENT阶段:

1
2
3
4
5
6
7
8
9
10
11
12
[root@node01 ~]# kubectl exec -it -n system node1-59c9475bc6-zkhq5 bash
[root@node1-59c9475bc6-zkhq5]# exit
[root@node01 ~]# kubectl exec -it -n system node1-59c9475bc6-zkhq5 bash
[root@node1-59c9475bc6-zkhq5]# exit
[root@node01 ~]# kubectl exec -it -n system node1-59c9475bc6-zkhq5 bash
[root@node1-59c9475bc6-zkhq5]# exit

[root@node01 ~]# netstat -anp|grep 23380
tcp 0 0 127.0.0.1:23380 0.0.0.0:* LISTEN 38914/kubelet
tcp 0 0 127.0.0.1:56369 127.0.0.1:23380 TIME_WAIT -
tcp 0 0 127.0.0.1:23380 127.0.0.1:57601 TIME_WAIT -
tcp 0 0 127.0.0.1:23380 127.0.0.1:57479 TIME_WAIT -

解决方案

  1. 业务根据实际情况调整文件句柄数。
  2. 针对业务量大的环境,强烈建议整体做一下操作系统层面的性能优化,否则,不定哪个系统参数就成了性能瓶颈,网上找了个调优案例[3],感兴趣的可以参考。

参考资料

  1. https://blog.csdn.net/pyxllq/article/details/80351827
  2. http://mdba.cn/2015/03/10/tcp-socket文件句柄泄漏
  3. https://www.shuzhiduo.com/A/RnJW7NLyJq/

问题背景

K8S集群内,Influxdb监控数据获取异常,最终CPU、内存和磁盘使用率都无法获取。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
监控项         使用率
CPU(核) 3%
内存(GB) 18%
磁盘空间(GB) 0%

监控项 使用率
CPU(核) 7%
内存(GB) 18%
磁盘空间(GB) 1%

监控项 使用率
CPU(核) 0%
内存(GB) 0%
磁盘空间(GB) 0%

...

Influxdb监控架构图参考[1],其中Load Balancer采用nginx实现:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
        ┌─────────────────┐                 
│writes & queries │
└─────────────────┘


┌───────────────┐
│ │
┌────────│ Load Balancer │─────────┐
│ │ │ │
│ └──────┬─┬──────┘ │
│ │ │ │
│ │ │ │
│ ┌──────┘ └────────┐ │
│ │ ┌─────────────┐ │ │┌──────┐
│ │ │/write or UDP│ │ ││/query│
│ ▼ └─────────────┘ ▼ │└──────┘
│ ┌──────────┐ ┌──────────┐ │
│ │ InfluxDB │ │ InfluxDB │ │
│ │ Relay │ │ Relay │ │
│ └──┬────┬──┘ └────┬──┬──┘ │
│ │ | | │ │
│ | ┌─┼──────────────┘ | │
│ │ │ └──────────────┐ │ │
│ ▼ ▼ ▼ ▼ │
│ ┌──────────┐ ┌──────────┐ │
│ │ │ │ │ │
└─▶│ InfluxDB │ │ InfluxDB │◀─┘
│ │ │ │
└──────────┘ └──────────┘

原因分析

因为获取的数据来源是influxdb数据库,所以先搞清楚异常的原因是请求路径上的问题,还是influxdb数据库自身没有数据的问题:

1
2
3
4
5
6
7
8
9
10
11
12
13
# 找到influxdb-nginx的service
kubectl get svc -n kube-system -owide
NAME TYPE CLUSTER-IP EXTERNAL-IP PORT(S) AGE SELECTOR
grafana-service ClusterIP 10.96.177.245 <none> 3000/TCP 21d app=grafana
heapster ClusterIP 10.96.239.225 <none> 80/TCP 21d app=heapster
influxdb-nginx-service ClusterIP 10.96.170.72 <none> 7076/TCP 21d app=influxdb-nginx
influxdb-relay-service ClusterIP 10.96.196.45 <none> 9096/TCP 21d app=influxdb-relay
influxdb-service ClusterIP 10.96.127.45 <none> 8086/TCP 21d app=influxdb

# 在集群节点上检查访问influxdb-nginx的service是否正常
curl -i 10.96.170.72:7076/query
HTTP/1.1 401 Unauthorized
Server: nginx/1.17.2

可以看出,请求发送到influxdb-nginxservice是正常的,也就是请求可以正常发送到后端的influxdb数据库。那就继续确认influxdb数据库自身没有数据的问题:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
# 找到influxdb数据库的pod
kubectl get pod -n kube-system -owide |grep influxdb
influxdb-nginx-4x8pr 1/1 Running 3 21d 177.177.52.201 node3
influxdb-nginx-tpngh 1/1 Running 6 21d 177.177.41.214 node1
influxdb-nginx-wh6kc 1/1 Running 5 21d 177.177.250.180 node2
influxdb-relay-rs-65c94bbf5f-dp7s4 1/1 Running 2 21d 177.177.250.148 node2
influxdb1-6ff9466d46-q6w5r 1/1 Running 3 21d 177.177.41.230 node1
influxdb2-d6d6697f5-zzcnk 1/1 Running 3 21d 177.177.250.161 node2
influxdb3-65ddfc7476-hxhr8 1/1 Running 4 21d 177.177.52.217 node3

# 登录任意一个influxdb容器内并进入交互式命令
kubectl exec -it -n kube-systme influxdb-rs3-65ddfc7476-hxhr8 bash
root@influxdb-rs3-65ddfc7476-hxhr8:/# influx
Connected to http://localhost:8086 version 1.7.7
InfluxDB shell version: 1.7.7
> auth
username: admin
password: xxx
> use xxx;
Using database xxx

根据业务层面的查询语句,在influxdb交互式命令下手工查询验证:

1
2
> select sum(value) from "cpu/node_capacity" where "type" = 'node' and "nodename" = 'node1' and time > now() - 2m
>

结果发现确实没有查到数据,既然2min内的数据没有,那把时间线拉长一些看看呢?

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
# 不限制时间范围的查询
> select sum(value) from "cpu/node_capacity"> select sum(value) from "cpu/node_capacity";
name: cpu/node_capacity
time sum
---- ---
0 5301432000

# 查询72min内的数据
> select sum(value) from "cpu/node_capacity" where "type" = 'node' and "nodename" = 'node1' and time > now() - 72m
name: cpu/node_capacity
time sum
---- ---
1624348319900503945 72000

# sleep 1min,继续查询72min内的数据
> select sum(value) from "cpu/node_capacity" where "type" = 'node' and "nodename" = 'node1' and time > now() - 72m
name: cpu/node_capacity
>

# 查询73min内的数据
> select sum(value) from "cpu/node_capacity" where "type" = 'node' and "nodename" = 'node1' and time > now() - 73m
name: cpu/node_capacity
time sum
---- ---
1624348319900503945 72000

根据查询结果看,不添加时间范围的查询是有记录的,并且通过多次验证看,数据无法获取的原因是数据在某个时间点不再写入导致的。查看influxdb的日志看看有没有什么相关日志:

1
2
3
4
5
6
kubectl logs -n kube-systme influxdb-rs3-65ddfc7476-hxhr8
ts=2021-06-22T09:56:49.658621Z lvl=warn msg="max-values-per-tag limit may be exceeded soon" log_id=0UYIcREl000 service=store perc=100% n=100000 max=100000 db_instance=xxx measurement=network/rx tag=pod_name
ts=2021-06-22T09:56:49.658702Z lvl=warn msg="max-values-per-tag limit may be exceeded soon" log_id=0UYIcREl000 service=store perc=100% n=100000 max=100000 db_instance=xxx measurement=network/rx_errors tag=pod_name
ts=2021-06-22T09:56:49.658815Z lvl=warn msg="max-values-per-tag limit may be exceeded soon" log_id=0UYIcREl000 service=store perc=100% n=100000 max=100000 db_instance=xxx measurement=network/tx tag=pod_name
ts=2021-06-22T09:56:49.658893Z lvl=warn msg="max-values-per-tag limit may be exceeded soon" log_id=0UYIcREl000 service=store perc=100% n=100000 max=100000 db_instance=xxx measurement=network/tx_errors tag=pod_name
ts=2021-06-22T09:56:49.659062Z lvl=warn msg="max-values-per-tag limit may be exceeded soon" log_id=0UYIcREl000 service=store perc=100% n=100003 max=100000 db_instance=xxx measurement=uptime tag=pod_name

果然,有大量warn日志,提示max-values-per-tag limit may be exceeded soon,从日志可以看出,这个参数的默认值为100000。通过搜索,找到了这个参数引入的issue[2],引入原因大概意思是:

如果不小心加载了大量的cardinality数据,那么当我们删除数据的时候,InfluxDB很容易会发生OOM。

通过临时修改max-values-per-tag参数,验证问题是否解决

1
2
3
4
5
6
7
8
9
10
11
cat influxdb.conf
[meta]
dir = "/var/lib/influxdb/meta"
[data]
dir = "/var/lib/influxdb/data"
engine = "tsm1"
wal-dir = "/var/lib/influxdb/wal"
max-series-per-database = 0
max-values-per-tag = 0
[http]
auth-enabled = true
1
2
3
4
5
6
7
8
kubectl delete pod -n kube-system influxdb-rs1-6ff9466d46-q6w5r
pod "influxdb-rs1-6ff9466d46-q6w5r" deleted

kubectl delete pod -n kube-system influxdb-rs2-d6d6697f5-zzcnk
pod "influxdb-rs2-d6d6697f5-zzcnk" deleted

kubectl delete pod -n kube-system influxdb-rs3-65ddfc7476-hxhr8
pod "influxdb-rs3-65ddfc7476-hxhr8" deleted

再次观察业务层面获取的Influxdb监控数据,最终CPU、内存和磁盘使用率正常获取。

1
2
3
4
监控项         使用率
CPU(核) 19%
内存(GB) 22%
磁盘空间(GB) 2%

解决方案

根据业务情况,将influxdbmax-values-per-tag参数调整到合适值。

参考资料

  1. https://github.com/influxdata/influxdb-relay
  2. https://github.com/influxdata/influxdb/issues/7146