云原生知识星球
0%

发表于 更新于 分类于 阅读时长 ≈ 12 分钟

问题描述

Docker守护进程在异常断电后卡在activating状态，并且内存占用在无限增加。

1
2
3
4
5
6
7
8
9
10
11
12
[root@node01 docker]# service docker status
Redirecting to /bin/systemctl status docker.service
● docker.service - Docker Application Container Engine
   Loaded: loaded (/usr/lib/systemd/system/docker.service; enabled; vendor preset: disabled)
  Drop-In: /etc/systemd/system/docker.service.d
           └─restart.conf
   Active: activating (start) since Tue 2021-12-07 15:44:32 CST; 1min 18s ago
     Docs: https:/docs.docker.com
 Main PID: 274797 (dockerd)
    Tasks: 481
   Memory: 15.4G  -- 占用不正常
   CGroup: /system
1
2
3
4
5
6
7
8
9
10
11
12
13
[root@node01 docker]# service docker status
Redirecting to /bin/systemctl status docker.service
● docker.service - Docker Application Container Engine
   Loaded: loaded (/usr/lib/systemd/system/docker.service; enabled; vendor preset: disabled)
  Drop-In: /etc/systemd/system/docker.service.d
           └─restart.conf
   Active: deactivating (stop-sigterm)
     Docs: https:/docs.docker.com
 Main PID: 274797 (dockerd)
    Tasks: 481
   Memory: 247.3G   -- 一直在疯狂增加
   CGroup: /system.slice/docker.service
           └─274

定位过程

首先，查看docker版本和docker info信息

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
[root@node01files]# docker version
Client: Docker Engine - Community
 Version:           20.10.7
 API version:       1.41
 Go version:        go1.13.15
 Git commit:        f0df350
 Built:             Wed Jun  2 11:58:10 2021
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.7
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.13.15
  Git commit:       b0f5bc3
runc:
  Version:          1.0.0-rc95
  GitCommit:        b9ee9c6314599f1b4a7f497e1f1f856fe433d3b7
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0
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
[root@node01 files]# docker info
Client:
 Context:    default
 Debug Mode: false
 Plugins:
  app: Docker App (Docker Inc., v0.9.1-beta3)
  buildx: Build with BuildKit (Docker Inc., v0.5.1-docker)
  scan: Docker Scan (Docker Inc., v0.8.0)

Server:
 Server Version: 20.10.7
 Storage Driver: overlay2
  Backing Filesystem: xfs
  Supports d_type: true
  Native Overlay Diff: true
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: systemd
 Cgroup Version: 1
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 io.containerd.runtime.v1.linux runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: d71fcd7d8303cbf684402823e425e9dd2e99285d
 runc version: b9ee9c6314599f1b4a7f497e1f1f856fe433d3b7
 init version: de40ad0
 Security Options:
   seccomp
   Profile: default
 Kernel Version: 3.10.0-957.21.3.el7.x86_64
 Operating System: CentOS 7.6
 OSType: linux
 Architecture: x86_64
 Total Memory: 256GiB
 Name: node01
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
  File Descriptors: 366
  Goroutines: 290
  EventsListeners: 0
 Registry: https:/index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: true

版本还算比较新，查看docker日志：

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
Dec 07 14:57:57 node01 dockerd[239420]: time="2021-12-07T14:57:57.831370861+08:00" level=info msg="Starting up"
Dec 07 14:57:57 node01 dockerd[239420]: time="2021-12-07T14:57:57.950367668+08:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Dec 07 14:57:57 node01 dockerd[239420]: time="2021-12-07T14:57:57.950430356+08:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Dec 07 14:57:57 node01 dockerd[239420]: time="2021-12-07T14:57:57.950486773+08:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix://run/containerd/containerd.sock  <nil> 0 <nil>}] <nil> <nil>}" module=grpc
Dec 07 14:57:57 node01 dockerd[239420]: time="2021-12-07T14:57:57.950524941+08:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Dec 07 14:57:58 node01 dockerd[239420]: time="2021-12-07T14:57:58.004622322+08:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Dec 07 14:57:58 node01 dockerd[239420]: time="2021-12-07T14:57:58.004663918+08:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Dec 07 14:57:58 node01 dockerd[239420]: time="2021-12-07T14:57:58.004697382+08:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix://run/containerd/containerd.sock  <nil> 0 <nil>}] <nil> <nil>}" module=grpc
Dec 07 14:57:58 node01 dockerd[239420]: time="2021-12-07T14:57:58.004726533+08:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Dec 07 14:58:14 node01 dockerd[239420]: time="2021-12-07T14:58:14.832862519+08:00" level=info msg="[graphdriver] using prior storage driver: overlay2"
Dec 07 14:59:00 node01 dockerd[239420]: time="2021-12-07T14:59:00.039554832+08:00" level=info msg="Loading containers: start."
Dec 07 15:02:27 node01 dockerd[239420]: fatal error: runtime: out of memory
Dec 07 15:02:27 node01 dockerd[239420]: runtime stack:
Dec 07 15:02:27 node01 dockerd[239420]: runtime.throw(0x5604d0deee9d, 0x16)
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/panic.go:774 +0x74
Dec 07 15:02:28 node01 dockerd[239420]: runtime.sysMap(0xfb6c000000, 0x5c000000, 0x5604d35dab58)
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/mem_linux.go:169 +0xc7
Dec 07 15:02:28 node01 dockerd[239420]: runtime.(*mheap).sysAlloc(0x5604d35be240, 0x5beee000, 0x7f6fd1fbab88, 0x5604cf22bf6b)
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/malloc.go:701 +0x1cf
Dec 07 15:02:28 node01 dockerd[239420]: runtime.(*mheap).grow(0x5604d35be240, 0x2df77, 0xffffffff)
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/mheap.go:1255 +0xa5
Dec 07 15:02:28 node01 dockerd[239420]: runtime.(*mheap).allocSpanLocked(0x5604d35be240, 0x2df77, 0x5604d35dab68, 0x5604cf212927)
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/mheap.go:1170 +0x268
Dec 07 15:02:28 node01 dockerd[239420]: runtime.(*mheap).alloc_m(0x5604d35be240, 0x2df77, 0x7f6c01180100, 0x7f6c01184350)
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/mheap.go:1022 +0xc6
Dec 07 15:02:28 node01 dockerd[239420]: runtime.(*mheap).alloc.func1()
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/mheap.go:1093 +0x4e
Dec 07 15:02:28 node01 dockerd[239420]: runtime.(*mheap).alloc(0x5604d35be240, 0x2df77, 0x7f6fd1010100, 0x7f6c01184350)
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/mheap.go:1092 +0x8c
Dec 07 15:02:28 node01 dockerd[239420]: runtime.largeAlloc(0x5beee000, 0x5604cf250001, 0x7f6c01184350)
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/malloc.go:1138 +0x99
Dec 07 15:02:28 node01 dockerd[239420]: runtime.mallocgc.func1()
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/malloc.go:1033 +0x48
Dec 07 15:02:28 node01 dockerd[239420]: runtime.systemstack(0x0)
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/asm_amd64.s:370 +0x63
Dec 07 15:02:28 node01 dockerd[239420]: runtime.mstart()
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/proc.go:1146
Dec 07 15:02:28 node01 dockerd[239420]: goroutine 1 [running]:
Dec 07 15:02:28 node01 dockerd[239420]: runtime.systemstack_switch()
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/asm_amd64.s:330 fp=0xc0008bff70 sp=0xc0008bff68 pc=0x5604cf2528e0
Dec 07 15:02:28 node01 dockerd[239420]: runtime.mallocgc(0x5beee000, 0x5604d1e8fde0, 0x1, 0x0)
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/malloc.go:1032 +0x8a7 fp=0xc0008c0010 sp=0xc0008bff70 pc=0x5604cf200ef7
Dec 07 15:02:28 node01 dockerd[239420]: runtime.growslice(0x5604d1e8fde0, 0xef119e4000, 0x3107eaa, 0x3107eaa, 0x3107eab, 0x5604cf20146b, 0xfb6bbbfb80, 0x7f6c01184350)
Dec 07 15:02:28 node01 dockerd[239420]: /usr/local/go/src/runtime/slice.go:181 +0x1e4 fp=0xc0008c0078 sp=0xc0008c0010 pc=0x5604cf23b0b4
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/go.etcd.io/bbolt.(*Cursor).first(0xc0008c0288)
Dec 07 15:02:28 node01 dockerd[239420]: docker/vendor/go.etcd.io/bbolt/cursor.go:182 +0x138 fp=0xc0008c00d8 sp=0xc0008c0078 pc=0x5604d012d348
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/go.etcd.io/bbolt.(*Cursor).next(0xc0008c0288, 0x0, 0x9f, 0x9f, 0x7f7150506429, 0x2b8, 0xc0008c0188, 0x5604cf23ee10)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/go.etcd.io/bbolt/cursor.go:234 +0x84 fp=0xc0008c0128 sp=0xc0008c00d8 pc=0x5604d012d684
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/go.etcd.io/bbolt.(*Cursor).Next(0xc0008c0288, 0x7f715050638a, 0x9f, 0x9f, 0xfb6bbcf720, 0x9f, 0x2b8)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/go.etcd.io/bbolt/cursor.go:75 +0x43 fp=0xc0008c0198 sp=0xc0008c0128 pc=0x5604d012ca43
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libkv/store/boltdb.(*BoltDB).List.func1(0xc0034350a0, 0xc0008c0200, 0xc0034350a0)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libkv/store/boltdb/boltdb.go:288 +0x19a fp=0xc0008c02b8 sp=0xc0008c0198 pc=0x5604d0142a4a
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/go.etcd.io/bbolt.(*DB).View(0xc0001dc200, 0xc0008c03f8, 0x0, 0x0)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/go.etcd.io/bbolt/db.go:725 +0xaa fp=0xc0008c0340 sp=0xc0008c02b8 pc=0x5604d0130a3a
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libkv/store/boltdb.(*BoltDB).List(0xc00482f2c0, 0xc001a7af00, 0x5e, 0x0, 0x0, 0x0, 0x0, 0x0)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libkv/store/boltdb/boltdb.go:279 +0x1b3 fp=0xc0008c0430 sp=0xc0008c0340 pc=0x5604d0141583
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libnetwork/datastore.(*cache).kmap(0xc003bf5900, 0x5604d220c1a0, 0xc001e7c160, 0x0, 0x5e, 0xc001a7ae40)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libnetwork/datastore/cache.go:43 +0x286 fp=0xc0008c0560 sp=0xc0008c0430 pc=0x5604cfcc81a6
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libnetwork/datastore.(*cache).list(0xc003bf5900, 0x5604d220c1a0, 0xc001e7c160, 0x0, 0x0, 0x0, 0x0, 0x0)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libnetwork/datastore/cache.go:164 +0x7e fp=0xc0008c0678 sp=0xc0008c0560 pc=0x5604cfcc988e
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libnetwork/datastore.(*datastore).List(0xc0079ff680, 0xc001a7ae40, 0x5e, 0x5604d220c1a0, 0xc001e7c160, 0x0, 0x0, 0x0, 0x0, 0x0)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libnetwork/datastore/datastore.go:517 +0x205 fp=0xc0008c0730 sp=0xc0008c0678 pc=0x5604cfccc745
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libnetwork.(*network).getEndpointsFromStore(0xc00289a380, 0xc004a99258, 0x7, 0x5604d2206920, 0xc001a515f0, 0xc002f3ff48)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libnetwork/store.go:190 +0x343 fp=0xc0008c09f8 sp=0xc0008c0730 pc=0x5604d01acaf3
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libnetwork.(*controller).reservePools(0xc0004b7400)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libnetwork/controller.go:977 +0x4c1 fp=0xc0008c0c28 sp=0xc0008c09f8 pc=0x5604d0159701
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libnetwork.New(0xc001055d00, 0x9, 0x10, 0xc0007ac870, 0xc001387fb0, 0xc001055d00, 0x9)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/vendor/libnetwork/controller.go:245 +0x615 fp=0xc0008c0dd8 sp=0xc0008c0c28 pc=0x5604d0154815
Dec 07 15:02:28 node01 dockerd[239420]: /docker/daemon.(*Daemon).initNetworkController(0xc00000c1e0, 0xc000207080, 0xc001387fb0, 0xc000236f50, 0xc00000c1e0, 0xc0007170c8, 0xc001387fb0)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/daemon/daemon_unix.go:855 +0xa9 fp=0xc0008c0e90 sp=0xc0008c0dd8 pc=0x5604d0a49429
Dec 07 15:02:28 node01 dockerd[239420]: /docker/daemon.(*Daemon).restore(0xc00000c1e0, 0xc00004e5c0, 0xc000220000)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/daemon/daemon.go:490 +0x50b fp=0xc0008c1088 sp=0xc0008c0e90 pc=0x5604d0a3898b
Dec 07 15:02:28 node01 dockerd[239420]: /docker/daemon.NewDaemon(0x5604d21de4c0, 0xc00004e5c0, 0xc000207080, 0xc0007ac870, 0x0, 0x0, 0x0)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/daemon/daemon.go:1147 +0x2be8 fp=0xc0008c19c8 sp=0xc0008c1088 pc=0x5604d0a3c938
Dec 07 15:02:28 node01 dockerd[239420]: main.(*DaemonCli).start(0xc0007ab410, 0xc000218600, 0x0, 0x0)
Dec 07 15:02:28 node01 dockerd[239420]: /docker/cmd/dockerd/daemon.go:195 +0x743 fp=0xc0008c1d00 sp=0xc0008c19c8 pc=0x5604d0dbb3c3
Dec 07 15:02:28 node01 dockerd[239420]: main.runDaemon(...)

日志中存在明显的异常堆栈打印，分析可知，启动过程中走到Loading containers: start.之后卡住，然后打印fatal error: runtime: out of memory，也就是内存爆了。根据堆栈信息，可以看出异常的调用路径如下：

1
NewDaemon —> restore() —> initNetworkController —> libnetwork.New() —> reservePools() —>  getEndpointsFromStore() —> List —> cache.list(kvObject) —> cache.kmap(kvObject) —> List(keyPrefix) —> Next —> next —> first

拉取对应版本的代码，根据上述调用过程，找到指定的代码位置：

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
// List returns the range of keys starting with the passed in prefix
func (b *BoltDB) List(keyPrefix string) ([]*store.KVPair, error) {
    var (
        db  *bolt.DB
        err error
    )
    b.Lock()
    defer b.Unlock()

    kv := []*store.KVPair{}

    if db, err = b.getDBhandle(); err != nil {
        return nil, err
    }
    defer b.releaseDBhandle()

    err = db.View(func(tx *bolt.Tx) error {
        bucket := tx.Bucket(b.boltBucket)
        if bucket == nil {
            return store.ErrKeyNotFound
        }

        cursor := bucket.Cursor()
        prefix := []byte(keyPrefix)

        for key, v := cursor.Seek(prefix); bytes.HasPrefix(key, prefix); key, v = cursor.Next() {

            dbIndex := binary.LittleEndian.Uint64(v[:libkvmetadatalen])
            v = v[libkvmetadatalen:]
            val := make([]byte, len(v))
            copy(val, v)

            kv = append(kv, &store.KVPair{
                Key:       string(key),
                Value:     val,
                LastIndex: dbIndex,
            })
        }
        return nil
    })
    if len(kv) == 0 {
        return nil, store.ErrKeyNotFound
    }
    return kv, err
}

可以看出，这段是读取boltdb数据库（用于缓存网络配置），从之前了解看，这个数据库在异常断电时很容易损坏，所以怀疑是数据库损坏了，导致此处的遍历读取超出了预期的循环次数，而每次循环都会创建变量，分配内存，最终被内核OOM。

在docker社区查找相关issue[1] [2]，发现确实存在boltdb数据库损坏的现象，不过最终报错的现象不太一样。最后，在docker社区也提了个issue[3]，社区反馈也是怀疑boltdb数据库损坏，并建议可以把local-kv.db文件删除再重启来恢复。

个人觉得，上面报错的地方可以优化一下，对db文件做一次检查，如果检查到异常，提前抛异常，而不是不停地吃内存（由于异常的环境被破坏了，这个想法需要等复现后再考虑优化）。

解决方案

  1. 临时解决：删除local-kv.db文件再重启docker服务。
  2. 永久解决：优化异常代码。

参考资料

  1. https://github.com/moby/moby/issues/37238
  2. https://github.com/moby/moby/issues/42099
  3. https://github.com/moby/moby/issues/43072

发表于 更新于 分类于 阅读时长 ≈ 13 分钟

问题背景

karaf框架没有直接依赖log4j包，所以简单的升级项目中的log4j或实际项目中没有log4j，都无法解决最近发现的漏洞问题（CVE-2021-44228、CVE-2021-45046、CVE-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
...

修改version和jdkHome字段：

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-api和pax-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

发表于 更新于 分类于 阅读时长 ≈ 4 分钟

本次发现的问题是踩到了老版本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 会将 configmap 中 subpath 指定的文件 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 。

发表于 更新于 分类于 阅读时长 ≈ 4 分钟

功能总结

导出数据包

方法：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 秒的数据。

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

发表于 更新于 分类于 阅读时长 ≈ 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

发表于 更新于 分类于 阅读时长 ≈ 4 分钟

问题背景

使用附加网络的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

发表于 更新于 分类于 阅读时长 ≈ 11 分钟

问题背景

通过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-apiserver的DELETE接口（默认带grace-period=30s）；
  2. 第一次的删除只是更新Pod对象的元信息（DeletionTimestamp字段和DeletionGracePeriodSeconds字段），并没有在Etcd中删除记录；
  3. kubectl命令的执行会阻塞并显示正在删除Pod；
  4. kubelet组件监听到Pod对象的更新事件，执行killPod()方法；
  5. kubelet组件监听到pod的删除事件，第二次调用kube-apiserver的DELETE接口（带grace-period=0）
  6. kube-apiserver的DELETE接口去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日志之后会有DELETE和REMOVE的操作，这也就说明问题出在第二次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=94549的glusterfs进程在占用挂载点所在目录，看看是什么进程：

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-xxx和cam-xxx没有任何关联。由此推断出是glusterfs管理的挂载信息发送错乱导致，具体错乱原因就转给相关负责的同事看了。

解决方案

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

参考资料

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

发表于 更新于 分类于 阅读时长 ≈ 3 分钟

问题背景

部署在服务器上的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上ping和ssh服务器都没有问题，说明是配置导致的部分协议的连接问题；

后来提供环境的人排查交换机配置，发现GRE隧道的默认MTU为1464，而集群网卡上的MTU为1500，最后协商出的MSS为1460（见抓包中的前两个报文）：

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字节，所以出现了上述现象，同时也解释了http和ftp有问题（长报文），而ping和ssh没有问题（短报文）。

解决方案

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

设置TCP的MSS参考命令：

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

发表于 更新于 分类于 阅读时长 ≈ 5 分钟

问题背景

如下所示，用户使用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

发表于 更新于 分类于 阅读时长 ≈ 2 分钟

问题背景

接上次的问题，一段时间后，环境再次出现harbor和calico因为健康检查不过反复重启的问题，并且使用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]，排查是否相同问题；
  4. …

摸索一番，没发现什么异常。回过头来想想，既然是业务下发大量配置导致的，并且影响是全局的（除了业务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/