派猴子来的救兵

15 Feb, 2023

cgroup memory limit 是不是计算 page cache

测试环境

OS: CentOS Linux release 7.6.1810 (Core) ; KERNEL 5.10.56 ; Cgroup: v1

问题

一个问题，Cgroup 下面的进程读写文件，就会生成 page cache。这部分内存使用计算到 Cgroup Memory Limit 里面吗？

我感觉是不会的（其实会），因为如果会的话，会引出下面这个问题：

问题二：系统怎么知道这个 page cache 属于哪个进程？

A 读了一个文件之后，B 又读了，那这个 page cache 是同时算到 A 和 B 进程里面？

A 读了之后，B 又使用到，那就算到 B 头上了？从 A 里面去掉？

结果

直接说测试下来的结果吧。

page cache 会计算到 cgroup limit 里面。

但内存超的时候，不会直接触发 OOM Killer，而是会清理部分 page cache。

page cache 始终算在第一个使用它的进程（以及对应的 Cgroup）上。

清理策略

多提一句，cgroup v2 的清理 page cache 策略应该比 v1 有优化，参考如下：

Another important topic in cgroup v2, which was unachievable with the previous v1, is a proper way of tracking Page Cache IO writebacks. The v1 can’t understand which memory cgroup generates disk IOPS and therefore, it incorrectly tracks and limits disk operations. Fortunately, the new v2 version fixes these issues. It already provides a bunch of new features which can help with Page Cache writeback.

https://biriukov.dev/docs/page-cache/6-cgroup-v2-and-page-cache/

验证

准备工作

创建几个文件待用

# dd if=/dev/random of=1 bs=1000000 count=500
500+0 records in
500+0 records out
500000000 bytes (500 MB) copied, 3.03696 s, 165 MB/s
[root@test-page-cache]# for i in {1..6} ; do dd if=/dev/random of=$i bs=1000000 count=500 ; done
500+0 records in
500+0 records out
500000000 bytes (500 MB) copied, 3.13473 s, 160 MB/s
500+0 records in
500+0 records out
500000000 bytes (500 MB) copied, 3.06832 s, 163 MB/s
500+0 records in
500+0 records out
500000000 bytes (500 MB) copied, 3.04262 s, 164 MB/s
500+0 records in
500+0 records out
500000000 bytes (500 MB) copied, 3.03191 s, 165 MB/s
500+0 records in
500+0 records out
500000000 bytes (500 MB) copied, 3.04711 s, 164 MB/s
500+0 records in
500+0 records out
500000000 bytes (500 MB) copied, 3.07169 s, 163 MB/s

清理一下page cache

[root@test-page-cache]# free -h
              total        used        free      shared  buff/cache   available
Mem:            22G        5.8G        2.8G        365M         14G         16G
Swap:          8.0G         16M        8.0G
[root@test-page-cache]# echo 3 > /proc/sys/vm/drop_caches
[root@test-page-cache]# free -h
              total        used        free      shared  buff/cache   available
Mem:            22G        5.3G         16G        365M        1.2G         16G
Swap:          8.0G         16M        8.0G

启动一个带 memory limit 的 docker 容器

docker run --rm -ti -v $PWD:/tmp/test-page-cache -w /tmp/test-page-cache --memory 1G alpine:3.16.2

测试1

测试1，是想验证一下 page cache 算在 limit 里面吗，以及触发了 limit 会怎么样？

读取两个之前生成的文件（每个文件500MB）

/tmp/test-page-cache # cat 1 > /dev/null
/tmp/test-page-cache # cat 2 > /dev/null

看一下 page cache 情况

[root@89e16b39fdc6da0f6c0e4d936aa0df8141ebe20d033fd8a7540ad0d550d8163c]# free -h
              total        used        free      shared  buff/cache   available
Mem:            22G        5.3G         15G        365M        2.6G         16G
Swap:          8.0G         16M        8.0G

# pwd
/sys/fs/cgroup/memory/docker/89e16b39fdc6da0f6c0e4d936aa0df8141ebe20d033fd8a7540ad0d550d8163c
# cat memory.usage_in_bytes
1073512448
# cat memory.stat
cache 1069584384
rss 106496
rss_huge 0
shmem 0
mapped_file 0
dirty 0
writeback 0
swap 0
pgpgin 488796
pgpgout 227651
pgfault 924
pgmajfault 0
inactive_anon 102400
active_anon 0
inactive_file 1069461504
active_file 0
unevictable 0
hierarchical_memory_limit 1073741824
hierarchical_memsw_limit 2147483648
total_cache 1069584384
total_rss 106496
total_rss_huge 0
total_shmem 0
total_mapped_file 0
total_dirty 0
total_writeback 0
total_swap 0
total_pgpgin 488796
total_pgpgout 227651
total_pgfault 924
total_pgmajfault 0
total_inactive_anon 102400
total_active_anon 0
total_inactive_file 1069461504
total_active_file 0
total_unevictable 0

在容器里面继续读文件

/tmp/test-page-cache # for i in 1 2 3 4 5 6 ; do echo $i ; cat $i > /dev/null ; done
1
2
3
4
5
6
/tmp/test-page-cache #

可以看到 page cache 不再增加了

# free -h
              total        used        free      shared  buff/cache   available
Mem:            22G        5.3G         14G        365M        2.7G         16G
Swap:          8.0G         16M        8.0G
# cat memory.stat
cache 1067421696
rss 241664
rss_huge 0
shmem 0
mapped_file 0
dirty 0
writeback 0
swap 0
pgpgin 1099560
pgpgout 838969
pgfault 1617
pgmajfault 0
inactive_anon 372736
active_anon 0
inactive_file 1067384832
active_file 0
unevictable 0
hierarchical_memory_limit 1073741824
hierarchical_memsw_limit 2147483648
total_cache 1067421696
total_rss 241664
total_rss_huge 0
total_shmem 0
total_mapped_file 0
total_dirty 0
total_writeback 0
total_swap 0
total_pgpgin 1099560
total_pgpgout 838969
total_pgfault 1617
total_pgmajfault 0
total_inactive_anon 372736
total_active_anon 0
total_inactive_file 1067384832
total_active_file 0
total_unevictable 0
# cat memory.usage_in_bytes
1073528832

使用 vmtouch 这样的工具，应该可以看到前一个文件的 cache 被清掉了。不方便安装，就不再继续验证了。

测试2

测试2是验证一下，page cache 算在第一个进程里面。其实就是说，如果文件已经在 page cache 里面了，再次 read 不会增加本进程所在cgroup 的 cache 值。

先在宿主机上面清理一下 page cache，准备一个干净的环境。然后在宿主机在 cat 一个文件，缓存到 page cache 里面。

# echo 3 > /proc/sys/vm/drop_caches
# free -h
              total        used        free      shared  buff/cache   available
Mem:            22G        5.3G         16G        365M        1.2G         16G
Swap:          8.0G         16M        8.0G
[root@VMS172906 ~]# cd /tmp/test-page-cache/
# cat 1 > /dev/null

然后在容器里面，再次 cat 1，可以看到容器的内存使用没有增加。

# cat memory.stat
cache 675840
rss 241664
rss_huge 0
shmem 0
mapped_file 0
dirty 0
writeback 0
swap 0
pgpgin 1100286
pgpgout 1100138
pgfault 2673
pgmajfault 0
inactive_anon 507904
active_anon 0
inactive_file 520192
active_file 0
unevictable 0
hierarchical_memory_limit 1073741824
hierarchical_memsw_limit 2147483648
total_cache 675840
total_rss 241664
total_rss_huge 0
total_shmem 0
total_mapped_file 0
total_dirty 0
total_writeback 0
total_swap 0
total_pgpgin 1100286
total_pgpgout 1100138
total_pgfault 2673
total_pgmajfault 0
total_inactive_anon 507904
total_active_anon 0
total_inactive_file 520192
total_active_file 0
total_unevictable 0

27 Jan, 2023
golang gc
https://tip.golang.org/doc/gc-guide

https://github.com/golang/go/issues/30333
27 Dec, 2022
根证书验证中的一点细节
很多时候，公司内部会使用私有证书。我们把私有根证书下载到本地并信任，就可以访问公司内的 HTTPS 域名了。

那具体一点说，我们访问 HTTPS 域名的时候，网站会把域名的证书推送给我们（一般来说是浏览器，或者是 curl 命令等），这个证书里面包含了 CN 以及公钥等信息。同时还包含证书链 – 中间证书直到根证书。链上的证书的信息是不完整的，比如说，根证书里面可能有 CN 信息，但没有公钥数据。

那么问题来了，我怎么知道这个证书需要使用哪个根证书去验证呢？通过对比 CN 吗？还是别的什么字段？

如果你知道这个答案，可以不用看下去了。如果不知道，也可以直接翻到最后一节看。

不好！出问题了！

突然接到隔壁组同事的电话，说他们访问我这边的一个应用，app.corp.com，报了证书过期的错误。

我第一反应是，这个域名大概在半年前证书过期了，导致了一次事故。难不成是又过期了？

马上打开电脑，打开网站，正常访问，查看证书信息，也没看到什么异常。（注：其实应该是有异常的，可能是 Edge 浏览器忽略了这个异常？后面换浏览器打不开网站。）

但同事给的报错截图上面写的清清楚楚，“证书过期”。

然后登陆到一台服务器上面，curl -v https://app.corp.com，发现果然有问题。上面显示 issuer’s certificate 过期。

我们的域名证书是由根证书直接签发的，难道说根证书过期了？

一直以来的理解都不对

一方面庆幸，还好不是我的锅了，另外一方面又想，如果根证书过期，事情就搞大了吧？

因为一直以来我对根证书的理解是这样的：

开天辟地之时，公司先创建一个私钥和公钥，然后拿私钥公钥做出来一个根证书 CA。这个 CA 呢，一方面用来签发其他子域名的证书，另外一方面，需要分发到每一台服务器以及员工的办公电脑上面。

按我这个理解的话，如果根证书过期了。就需要拿私钥公钥再重新做一个根证书，然后给每个子域名再签发证书，同时还要把新的根证书分发到每一台服务器以及员工办公电脑上。

这个工作量有些大。

并非如此

我们联系了 SRE 的同事。他们说是需要下载一个新的根证书，并更新到出问题的服务器，也就是调用我们服务的那个同事的服务器上，就可以了。（并不需要什么再签发子域名的证书。）

测下来也的确如此。

那么问题就来了，app.corp.com 传过来的证书，是怎么对应到新下载的根证书的呢？

Golang 代码答疑

在网上搜索了一下，并没有找到答案（可能是我的关键字给的不对）。不过一切都在代码里，去翻翻看代码吧。

Golang 的 tls 库里面有一个代码示例 https://pkg.go.dev/crypto/tls#example-Dial。从这里 debug 进去，仔细查看，终于明白了这其中机制。

简单来说，golang 会遍历所有的根证书，看看用根证书能不能解码 app.corp.com 的加密信息。如果可以，那就是我们要找的根证书。然后再看这个根证书是不是过期啊，等等。

再稍微多说一些细节呢。
1. golang 会首先会根证书做一个排序，优先验证更可能的根证书，比如说 CN 一样的。
2. golang 不会验证所有的根证书，这里面有一个硬编码，最多验证100个。
3. golang 验证到合法根证书之后，不会停下来，会尝试拿所有的证书链信息做后续的使用（这应该是一个 golang 可以改进的点）。黑盒测试的结果，curl 会停下来。也就是说，如果我们电脑上没有合法的根证书，客户端在根证书验证这里耗时会增加不少。

24 Nov, 2022

为什么 rsyslog 把 etcd 日志采集到了 kernel.log

etcd版本:

etcd Version: 3.4.9
Git SHA: 54ba95891
Go Version: go1.12.17
Go OS/Arch: linux/amd64

经测试，rsyslog 的下面这个配置导致日志采集到了 kernel.log

#### RULES ####

# Log all kernel messages to the console.
# Logging much else clutters up the screen.
kern.*                                                  /var/log/kernel

rsyslogd 版本

rsyslogd 8.29.0, compiled with:
	PLATFORM:				x86_64-redhat-linux-gnu
	PLATFORM (lsb_release -d):
	FEATURE_REGEXP:				Yes
	GSSAPI Kerberos 5 support:		No
	FEATURE_DEBUG (debug build, slow code):	No
	32bit Atomic operations supported:	Yes
	64bit Atomic operations supported:	Yes
	memory allocator:			system default
	Runtime Instrumentation (slow code):	No
	uuid support:				Yes
	Number of Bits in RainerScript integers: 64

See http://www.rsyslog.com for more information.

ETCD 在 journald 中的一条日志如下：

{
	"__CURSOR" : "s=78fdc2bf435b4aa6b7df9f50ff1e9c9f;i=662c5390;b=f3260b93a64641889bbf8fed67f4365a;m=2f4d3ea8e9fc;t=5ee329ba40462;x=82eb53b68142dca7",
	"__REALTIME_TIMESTAMP" : "1669276010546274",
	"__MONOTONIC_TIMESTAMP" : "52008810244604",
	"_BOOT_ID" : "f3260b93a64641889bbf8fed67f4365a",
	"PRIORITY" : "7",
	"SYSLOG_IDENTIFIER" : "etcd",
	"_TRANSPORT" : "journal",
	"_PID" : "840",
	"_UID" : "997",
	"_GID" : "993",
	"_COMM" : "etcd",
	"_EXE" : "/usr/local/bin/etcd",
	"_CMDLINE" : "/usr/local/bin/etcd --config-file /etc/etcd/etcd.conf.yml --log-output stderr",
	"_CAP_EFFECTIVE" : "0",
	"_SYSTEMD_CGROUP" : "/system.slice/etcd.service",
	"_SYSTEMD_UNIT" : "etcd.service",
	"_SYSTEMD_SLICE" : "system.slice",
	"_MACHINE_ID" : "c94b645006e94b62b253832779707d12",
	"_HOSTNAME" : "SVR15178IN5112",
	"PACKAGE" : "etcdserver/api/v3rpc",
	"MESSAGE" : "start time = 2022-11-24 15:46:50.545251478 +0800 CST m=+51575280.245951347, time spent = 821.324\uffffffc2\uffffffb5s, remote = 10.4.241.133:54952, response type = /etcdserverpb.KV/Txn, request count = 0, request size = 0, response count = 0, response size = 31, request content = compare:<key:\"cilium/state/identities/v1/id/292984\" version:0 > success:<request_put:<key:\"cilium/state/identities/v1/id/292984\" value_size:196 >> failure:<>",
	"_SOURCE_REALTIME_TIMESTAMP" : "1669276010546119"
}

粗看下来，是因为 etcd 使用一些库记录日志到 journald 的时候，没有加 FACILITY 字段。

rsyslog 采集日志的时候，会通过 PRIORITY » 3 的方式计算 FACILITY。计算结果为0，认为FACILITY 是 kernel。

Rsyslog 的一些 const value: https://github.com/rsyslog/rsyslog/blob/d083a2a2c20df6852a53e45f1e7a3f47679236d6/runtime/rsyslog.h#L202

#define	LOG_KERN	(0<<3)	/* kernel messages */
#define	LOG_USER	(1<<3)	/* random user-level messages */
#define	LOG_MAIL	(2<<3)	/* mail system */
#define	LOG_DAEMON	(3<<3)	/* system daemons */
#define	LOG_AUTH	(4<<3)	/* security/authorization messages */
#define	LOG_SYSLOG	(5<<3)	/* messages generated internally by syslogd */
#define	LOG_LPR		(6<<3)	/* line printer subsystem */
#define	LOG_NEWS	(7<<3)	/* network news subsystem */
#define	LOG_UUCP	(8<<3)	/* UUCP subsystem */

Rsyslog 计算 FACILITY 的宏 https://github.com/rsyslog/rsyslog/blob/d083a2a2c20df6852a53e45f1e7a3f47679236d6/runtime/rsyslog.h#L251

pri2fac(const syslog_pri_t pri)
{
	unsigned fac = pri >> 3;
	return (fac > 23) ? LOG_FAC_INVLD : fac;
}

2 Nov, 2022
[译]Linux下 OOMKiller 什么时候被触发
原文Roughly when the Linux Out-Of-Memory killer triggers (as of mid-2019)

原文发表时间，2019-08-11

因为某些别的原因，我最近想了解 Linux 里面 OOM Killer 是何时触发（以及不触发）的，以及为什么。这方面的详细文档不多，以及有些已经过时了。我在这里也没办法添加详细文档，因为这需要对 Linux 内核代码很了解，但我至少可以大概写些观点供我自己使用。

现如今有两种不同类型的 OOM Killer：全局的 OOM Killer 和依赖 cgroup 的 OOM Killer（后者通过cgroup 内存控制器实现）。我主要是对全局的感兴趣，部分是因为 cgroup OOM Killer 相对来说容易预测。

简单来说，当内核在分配物理内存页有有困难时，全局 OOM Killer 触发。当内核尝试分配内存页（不管用于任何用途，用于内核使用或需要内存页的进程）并且失败时，它将尝试各种方法来回收和压缩内存。如果成功了或至少取得了一些进展，内核会继续重试分配（我从代码中了解到）；如果他们未能释放内存页或取得进展，它会在许多（但不是全部）情况下触发 OOM Killer。

(比如说，内核申请连续大段内存页失败，是不会触发的，参考Decoding the Linux kernel’s page allocation failure messages。如果申请的连续内存小于等于 30KB 才会触发。git blame 显示从2007年就开始是这样的了。)
15 Aug, 2022
[译]SO_REUSEPORT选项
原文 The SO_REUSEPORT socket option [LWN.net]

One of the features merged in the 3.9 development cycle was TCP and UDP support for the SO_REUSEPORT socket option; that support was implemented in a series of patches by Tom Herbert. The new socket option allows multiple sockets on the same host to bind to the same port, and is intended to improve the performance of multithreaded network server applications running on top of multicore systems.

Linux 3.9 版本合并了一个 SO_REUSEPORT 的特性。可以在 TCP 和 UDP 的套接字上面配置 SO_REUSEPORT 这个选项；这项支持是 Tom Herbert 在一系列的补丁中实现的。这个新的套接字参数可以允许一台机器上面将多个套接字绑定在同一个端口上面，目的是为了提高多核机器上面的多线程网络服务应用的性能。
19 Jul, 2022
kafka-lib fetch api的数据解析
17 May, 2022
Journald Crash
昨天和芽哥一起查了一个 ETCD 切主的问题，挺有意思的，记录一下。

最终查明了根因，是使用 filebeat 采集 Journal 日志，引发 journald flush，导致高磁盘 IO，进而导致 ETCD 切主。
19 Apr, 2022
Docker Proxy
Proxy effect in dockerd(docker daemon) is different from that in docker cli.

Proxy setting in dockerd acts when dealing with registry, such as docker pull push login.

Command in dockerfile when doing docker build and docker run use proxy setting in docker cli (NOT automatically in environment way, see details below).

8 Apr, 2022

Docker Push 500 Path Not Found

最近几天 Harbor 出现比较多的 500 错误，引发告警。排查一下原因。

registry.log 里面的错误日志

Apr 6 11:46:40 172.25.0.1 registry[3915]: time=”2022-04-06T03:46:40.800755496Z” level=error msg=”response completed with error” auth.user.name=”harbor_registry_user” err.code=unknown err.detail=”s3aws: Path not found: /docker/registry/v2/repositories/gitlab-ci/100017681/_uploads/9ac3ea44-cbb6-4a1b-8048-6e59767c7370/data” err.message=”unknown error” go.version=go1.15.6 http.request.host=hub.xxx.com http.request.id=5bfcac34-34fa-4a05-ae52-b3fbb3714de2 http.request.method=PATCH http.request.remoteaddr=10.109.6.219 http.request.uri=”/v2/gitlab-ci/100017681/blobs/uploads/9ac3ea44-cbb6-4a1b-8048-6e59767c7370?_state=YmUOEA6F6k5OZsTu9CyQfl5CRNqlVEvx7XKgf_BVqLl7Ik5hbWUiOiJnaXRsYWItY2kvMTAwMDE3NjgxIiwiVVVJRCI6IjlhYzNlYTQ0LWNiYjYtNGExYi04MDQ4LTZlNTk3NjdjNzM3MCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAyMi0wNC0wNlQwMzo0NjozNi4yNTQ4MzA2MzRaIn0%3D” http.request.useragent=”docker/17.09.0-ce go/go1.8.3 git-commit/afdb6d4 kernel/4.19.118-1.el7.centos.x86_64 os/linux arch/amd64 UpstreamClient(Docker-Client/17.09.0-ce (linux))” http.response.contenttype=”application/json; charset=utf-8” http.response.duration=2.255332326s http.response.status=500 http.response.written=203 vars.name=”gitlab-ci/100017681” vars.uuid=9ac3ea44-cbb6-4a1b-8048-6e59767c7370

看代码梳理一下 docker push 的流程

Docker Cli 这边 upload blob 的流程是：

docker cli 调用 POST /v2//blobs/uploads/ 获取 uuid
docker cli 调用 PATCH /v2//blobs/uploads/

着重翻代码看一下 Registry 这边对这两个操作的对应的处理流程：

buh.StartBlobUpload
1. 调用到 s3.Writer(ctx context.Context, path string, append bool)。append = false
2. 调用到 d.S3.CreateMultipartUpload
3. 生成一个 UUID
4. 调用 S3 接口 Create 一个 Object。POST /{Bucket}/{Key+}?uploads
5. TLDR: 在 S3 创建一个对象，然后生成一个 UUID 并返回给 Client。
buh.PatchBlobData
1. 调用到 bub.ResumeBlobUpload
2. 调用到 blobs.Resume(buh, buh.UUID)
3. 调用到 s3.Writer(ctx context.Context, path string, append bool)。append = true
4. for _, multi := range d.S3.ListMultipartUploads{} 。遍历失败，返回 storagedriver.PathNotFoundError
5. TLDR: 按 UUID 找到对应的对象，然后写数据进去。

流程看起来问题不大，先创建对象，然后写数据。问题出在，第一步里面调用的 S3 创建对象是异步处理的，第二步请求来的时候，对象还没有创建好。

日志验证

通过看 S3 的 Harbor 的日志，基本上可以确定这个问题了。但还没有在代码层面看到异步的证据。应该是需要看 S3 SDK，一时看不动了。

我们拿一个出错的请求，来通过日志确认一下。

请求在 registry.log 里面的日志如下：

Apr  6 11:46:38 172.25.0.1 registry[3915]: time="2022-04-06T03:46:38.546533285Z" level=debug msg="authorizing request" go.version=go1.15.6 http.request.host=hub.xxx.com http.request.id=5bfcac34-34fa-4a05-ae52-b3fbb3714de2 http.request.method=PATCH http.request.remoteaddr=10.109.6.219 http.request.uri="/v2/gitlab-ci/100017681/blobs/uploads/9ac3ea44-cbb6-4a1b-8048-6e59767c7370?_state=YmUOEA6F6k5OZsTu9CyQfl5CRNqlVEvx7XKgf_BVqLl7Ik5hbWUiOiJnaXRsYWItY2kvMTAwMDE3NjgxIiwiVVVJRCI6IjlhYzNlYTQ0LWNiYjYtNGExYi04MDQ4LTZlNTk3NjdjNzM3MCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAyMi0wNC0wNlQwMzo0NjozNi4yNTQ4MzA2MzRaIn0%3D" http.request.useragent="docker/17.09.0-ce go/go1.8.3 git-commit/afdb6d4 kernel/4.19.118-1.el7.centos.x86_64 os/linux arch/amd64 UpstreamClient(Docker-Client/17.09.0-ce \(linux\))" vars.name="gitlab-ci/100017681" vars.uuid=9ac3ea44-cbb6-4a1b-8048-6e59767c7370
Apr  6 11:46:38 172.25.0.1 registry[3915]: time="2022-04-06T03:46:38.549190549Z" level=info msg="authorized request" go.version=go1.15.6 http.request.host=hub.xxx.com http.request.id=5bfcac34-34fa-4a05-ae52-b3fbb3714de2 http.request.method=PATCH http.request.remoteaddr=10.109.6.219 http.request.uri="/v2/gitlab-ci/100017681/blobs/uploads/9ac3ea44-cbb6-4a1b-8048-6e59767c7370?_state=YmUOEA6F6k5OZsTu9CyQfl5CRNqlVEvx7XKgf_BVqLl7Ik5hbWUiOiJnaXRsYWItY2kvMTAwMDE3NjgxIiwiVVVJRCI6IjlhYzNlYTQ0LWNiYjYtNGExYi04MDQ4LTZlNTk3NjdjNzM3MCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAyMi0wNC0wNlQwMzo0NjozNi4yNTQ4MzA2MzRaIn0%3D" http.request.useragent="docker/17.09.0-ce go/go1.8.3 git-commit/afdb6d4 kernel/4.19.118-1.el7.centos.x86_64 os/linux arch/amd64 UpstreamClient(Docker-Client/17.09.0-ce \(linux\))" vars.name="gitlab-ci/100017681" vars.uuid=9ac3ea44-cbb6-4a1b-8048-6e59767c7370
Apr  6 11:46:38 172.25.0.1 registry[3915]: time="2022-04-06T03:46:38.549281495Z" level=debug msg="(*linkedBlobStore).Resume" auth.user.name="harbor_registry_user" go.version=go1.15.6 http.request.host=hub.xxx.com http.request.id=5bfcac34-34fa-4a05-ae52-b3fbb3714de2 http.request.method=PATCH http.request.remoteaddr=10.109.6.219 http.request.uri="/v2/gitlab-ci/100017681/blobs/uploads/9ac3ea44-cbb6-4a1b-8048-6e59767c7370?_state=YmUOEA6F6k5OZsTu9CyQfl5CRNqlVEvx7XKgf_BVqLl7Ik5hbWUiOiJnaXRsYWItY2kvMTAwMDE3NjgxIiwiVVVJRCI6IjlhYzNlYTQ0LWNiYjYtNGExYi04MDQ4LTZlNTk3NjdjNzM3MCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAyMi0wNC0wNlQwMzo0NjozNi4yNTQ4MzA2MzRaIn0%3D" http.request.useragent="docker/17.09.0-ce go/go1.8.3 git-commit/afdb6d4 kernel/4.19.118-1.el7.centos.x86_64 os/linux arch/amd64 UpstreamClient(Docker-Client/17.09.0-ce \(linux\))" vars.name="gitlab-ci/100017681" vars.uuid=9ac3ea44-cbb6-4a1b-8048-6e59767c7370
Apr  6 11:46:38 172.25.0.1 registry[3915]: time="2022-04-06T03:46:38.552098655Z" level=debug msg="s3aws.GetContent("/docker/registry/v2/repositories/gitlab-ci/100017681/_uploads/9ac3ea44-cbb6-4a1b-8048-6e59767c7370/startedat")" auth.user.name="harbor_registry_user" go.version=go1.15.6 http.request.host=hub.xxx.com http.request.id=5bfcac34-34fa-4a05-ae52-b3fbb3714de2 http.request.method=PATCH http.request.remoteaddr=10.109.6.219 http.request.uri="/v2/gitlab-ci/100017681/blobs/uploads/9ac3ea44-cbb6-4a1b-8048-6e59767c7370?_state=YmUOEA6F6k5OZsTu9CyQfl5CRNqlVEvx7XKgf_BVqLl7Ik5hbWUiOiJnaXRsYWItY2kvMTAwMDE3NjgxIiwiVVVJRCI6IjlhYzNlYTQ0LWNiYjYtNGExYi04MDQ4LTZlNTk3NjdjNzM3MCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAyMi0wNC0wNlQwMzo0NjozNi4yNTQ4MzA2MzRaIn0%3D" http.request.useragent="docker/17.09.0-ce go/go1.8.3 git-commit/afdb6d4 kernel/4.19.118-1.el7.centos.x86_64 os/linux arch/amd64 UpstreamClient(Docker-Client/17.09.0-ce \(linux\))" trace.duration=2.760534ms trace.file="/go/src/github.com/docker/distribution/registry/storage/driver/base/base.go" trace.func="github.com/docker/distribution/registry/storage/driver/base.(*Base).GetContent" trace.id=aa22d5f1-24db-4d80-8867-bec6b3daadc2 trace.line=95 vars.name="gitlab-ci/100017681" vars.uuid=9ac3ea44-cbb6-4a1b-8048-6e59767c7370
Apr  6 11:46:40 172.25.0.1 registry[3915]: time="2022-04-06T03:46:40.800564701Z" level=debug msg="s3aws.Writer("/docker/registry/v2/repositories/gitlab-ci/100017681/_uploads/9ac3ea44-cbb6-4a1b-8048-6e59767c7370/data", true)" auth.user.name="harbor_registry_user" go.version=go1.15.6 http.request.host=hub.xxx.com http.request.id=5bfcac34-34fa-4a05-ae52-b3fbb3714de2 http.request.method=PATCH http.request.remoteaddr=10.109.6.219 http.request.uri="/v2/gitlab-ci/100017681/blobs/uploads/9ac3ea44-cbb6-4a1b-8048-6e59767c7370?_state=YmUOEA6F6k5OZsTu9CyQfl5CRNqlVEvx7XKgf_BVqLl7Ik5hbWUiOiJnaXRsYWItY2kvMTAwMDE3NjgxIiwiVVVJRCI6IjlhYzNlYTQ0LWNiYjYtNGExYi04MDQ4LTZlNTk3NjdjNzM3MCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAyMi0wNC0wNlQwMzo0NjozNi4yNTQ4MzA2MzRaIn0%3D" http.request.useragent="docker/17.09.0-ce go/go1.8.3 git-commit/afdb6d4 kernel/4.19.118-1.el7.centos.x86_64 os/linux arch/amd64 UpstreamClient(Docker-Client/17.09.0-ce \(linux\))" trace.duration=2.248339896s trace.file="/go/src/github.com/docker/distribution/registry/storage/driver/base/base.go" trace.func="github.com/docker/distribution/registry/storage/driver/base.(*Base).Writer" trace.id=8dfdaa69-9ace-4c3e-86cc-ef9c330b5106 trace.line=142 vars.name="gitlab-ci/100017681" vars.uuid=9ac3ea44-cbb6-4a1b-8048-6e59767c7370
Apr  6 11:46:40 172.25.0.1 registry[3915]: time="2022-04-06T03:46:40.800637996Z" level=error msg="error resolving upload: s3aws: Path not found: /docker/registry/v2/repositories/gitlab-ci/100017681/_uploads/9ac3ea44-cbb6-4a1b-8048-6e59767c7370/data" auth.user.name="harbor_registry_user" go.version=go1.15.6 http.request.host=hub.xxx.com http.request.id=5bfcac34-34fa-4a05-ae52-b3fbb3714de2 http.request.method=PATCH http.request.remoteaddr=10.109.6.219 http.request.uri="/v2/gitlab-ci/100017681/blobs/uploads/9ac3ea44-cbb6-4a1b-8048-6e59767c7370?_state=YmUOEA6F6k5OZsTu9CyQfl5CRNqlVEvx7XKgf_BVqLl7Ik5hbWUiOiJnaXRsYWItY2kvMTAwMDE3NjgxIiwiVVVJRCI6IjlhYzNlYTQ0LWNiYjYtNGExYi04MDQ4LTZlNTk3NjdjNzM3MCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAyMi0wNC0wNlQwMzo0NjozNi4yNTQ4MzA2MzRaIn0%3D" http.request.useragent="docker/17.09.0-ce go/go1.8.3 git-commit/afdb6d4 kernel/4.19.118-1.el7.centos.x86_64 os/linux arch/amd64 UpstreamClient(Docker-Client/17.09.0-ce \(linux\))" vars.name="gitlab-ci/100017681" vars.uuid=9ac3ea44-cbb6-4a1b-8048-6e59767c7370
Apr  6 11:46:40 172.25.0.1 registry[3915]: time="2022-04-06T03:46:40.800755496Z" level=error msg="response completed with error" auth.user.name="harbor_registry_user" err.code=unknown err.detail="s3aws: Path not found: /docker/registry/v2/repositories/gitlab-ci/100017681/_uploads/9ac3ea44-cbb6-4a1b-8048-6e59767c7370/data" err.message="unknown error" go.version=go1.15.6 http.request.host=hub.xxx.com http.request.id=5bfcac34-34fa-4a05-ae52-b3fbb3714de2 http.request.method=PATCH http.request.remoteaddr=10.109.6.219 http.request.uri="/v2/gitlab-ci/100017681/blobs/uploads/9ac3ea44-cbb6-4a1b-8048-6e59767c7370?_state=YmUOEA6F6k5OZsTu9CyQfl5CRNqlVEvx7XKgf_BVqLl7Ik5hbWUiOiJnaXRsYWItY2kvMTAwMDE3NjgxIiwiVVVJRCI6IjlhYzNlYTQ0LWNiYjYtNGExYi04MDQ4LTZlNTk3NjdjNzM3MCIsIk9mZnNldCI6MCwiU3RhcnRlZEF0IjoiMjAyMi0wNC0wNlQwMzo0NjozNi4yNTQ4MzA2MzRaIn0%3D" http.request.useragent="docker/17.09.0-ce go/go1.8.3 git-commit/afdb6d4 kernel/4.19.118-1.el7.centos.x86_64 os/linux arch/amd64 UpstreamClient(Docker-Client/17.09.0-ce \(linux\))" http.response.contenttype="application/json; charset=utf-8" http.response.duration=2.255332326s http.response.status=500 http.response.written=203 vars.name="gitlab-ci/100017681" vars.uuid=9ac3ea44-cbb6-4a1b-8048-6e59767c7370

对应的 Registry Access log 如下：

第一步请求：

request-1

第二步请求：

request-2

第一步中对应的 S3 的 Access 日志如下：

request-3

可以看到两点：

请求 2.2 秒才返回，但 Registry 这边 58 毫秒就返回了。所以怀疑是异步。
S3 请求处理完的时候，Client 这边的第二步已经执行了，导致 PathNotFoundError。

测试环境

问题

结果

清理策略

验证

准备工作

测试1

测试2

不好！出问题了！

一直以来的理解都不对

并非如此

Golang 代码答疑

registry.log 里面的错误日志

看代码梳理一下 docker push 的流程

日志验证