周星星 | 03 Feb 2016 | ( words)

记一次 strace 追踪的 Docker + VirtualBox 的底层 bug

最近在公司搭建一个基于 Docker 的 PHP 环境。

背景知识

  1. Docker 是一种容器技术，它可以提供一个隔离的环境，让用户的程序运行在一个完全隔离的虚拟的系统里，但 Docker 不是虚拟化，使用 Docker 可以在 Linux 上实现对于任意程序打包一次，到处运行。愿意接受安利的同学请移步 http://docker.io 。
  2. Mac OS X 的内核可以算是半个 BSD，Docker 依赖一些的 Linux 容器相关的技术是 OS X 不支持的，所以需要通过一个虚拟机运行 Linux 来使用。
  3. Docker 官方提供了一个方便 OS X 用户的名为 "dockertoolbox" 的软件包，包括这些内容：Docker CLI 客户端 + Docker Machine CLI 管理界面 + Docker 仓库 + VirtualBox + CoreOS + Kitematic （一个管理容器的GUI界面）。其中 CoreOS 是专门为虚拟化和容器技术设计的一个 Linux 发行版，精简到了只剩容器和虚拟化需要的一些组件，所以性能非常好。

问题出现

因为搭建 Docker PHP 环境的需要，已经把自己日常的业务开发迁移到了 Docker 上。如同往常一样 git pull 拉下最新代码，然后用浏览器打开正在开发中的项目，发现页面上一片空白了，打开 Chrome 的控制台，出现 Javascript 相关的报错，并且在文件底部发现一连串的乱码：

�����������������

用 curl 拉下来然后用 vim 打开如下：

想当然的认为这可能是前端的锅。于是和前端的同学，一起打开文件进行对比，但并没有发现非常可疑的点。然后就觉得是 Tengine 产生的问题，因为切换到自己的真实的宿主机用 Nginx 1.8.0 访问，没有这个问题。切换到 Docker 的环境就有这个问题，而两者的配置又几乎是一样的。

为了验证是否是 Tengine 产生的问题，在 Docker 容器中依次安装了 Tengine 2.1.2 (最新版), Nginx 1.9.10 (最新版), Nginx 1.8.0 (和宿主机相同)，均采用同一配置文件进行启动，然而无一幸免的都还是出现了这个问题。

用排除法的话就可以认为问题可能在网络通信或者是容器本体上了，尝试先排除网络的影响。绕过网络的映射，直接在 Docker 的容器内部使用 curl 访问来检查，发现仍然存在这个问题，所以问题基本可以限定在容器上面。

进一步排查

为了验证到底是不是容器产生的问题，在运维同学的建议下，第二天在虚拟机中特意安装了一个 CentOS 6.7，以及安装上公司运维组预编译的 PHP 和 Tengine 的 RPM 包，然后采用完全一样的配置，再次用 curl 访问同样的文件，没有观察到这个现象。所以确实可以确定已经是容器产生的问题。

尽管这里几乎已经确定问题是哪里产生的，仍然陷入了死胡同，想要 Google 也不知道到底用什么关键词。这个时候再试着在 Tengine 的日志中输出的 HTTP Response 的消息体给记录下来，在 Tengine 的配置中加上了这些代码，用 Lua 来获取 HTTP 的 Response，并记录进日志：

log_format bodylog '$remote_addr - $remote_user [$time_local] '  
      '"$request" $status $body_bytes_sent '
      '"$http_referer" "$http_user_agent" $request_time '
      '<"$request_body" >"$resp_body"';

lua_need_request_body on;  
# 上面的配置加入 http {} 区域

  access_log /tmp/access.log bodylog;
  set $resp_body "";
  body_filter_by_lua '
    local resp_body = string.sub(ngx.arg[1], 1, 10000) #10000这里是sub函数的截取长度，可以按需要改大点
    ngx.ctx.buffered = (ngx.ctx.buffered or "") .. resp_body
    if ngx.arg[2] then
      ngx.var.resp_body = ngx.ctx.buffered
    end
  ';
# 上面的配置加入 server {} 区域
# 然后开启对应的 access_log 即可

(来自 https://gist.github.com/morhekil/1ff0e902ed4de2adcb7a)

不过遗憾的是，访问日志里面并没有出现乱码，而在 curl 的结果中，乱码又确实还是存在的。

strace 登场

事已至此，想到可能需要对 Tengine 或者 Nginx 调试一下可能才能发现到底问题是出在什么地方了。所以想到了曾经跟踪一个 PHP 的 Segmentation Fault 时用过的 strace，它可以打印出一个进程的所有的系统调用(System Call)，从而观察程序大致上做了一些什么事情。于是马上安装上 strace，用带 -f 的参数来运行 Tengine。

strace -f tengine

(# -f 参数是 follow forks，因为 Tengine / NGINX 的实际接受用户请求的 Worker 是 fork 新建的进程)

然后照常用 curl 进行请求，获得输出：

...
[pid 22866] epoll_wait(11, {}, 512, 100) = 0
[pid 22866] epoll_wait(11, {}, 512, 100) = 0
[pid 22866] epoll_wait(11, {}, 512, 100) = 0
[pid 22866] epoll_wait(11, {}, 512, 100) = 0
[pid 22866] epoll_wait(11,  <unfinished ...>
[pid 22865] <... epoll_wait resumed> {?} 0x7f0d78c9b000, 512, -1) = 1
[pid 22865] accept4(7, 0x7ffc7958c0b0, 0x7ffc7958c12c, SOCK_NONBLOCK) = 11
[pid 22865] epoll_ctl(9, EPOLL_CTL_ADD, 11, {...}) = 0
[pid 22865] epoll_wait(9, {?} 0x7f0d78c9b000, 512, 60000) = 1
[pid 22865] recvfrom(11, 0x7f0d78c3d800, 1024, 0, NULL, NULL) = 126
[pid 22865] stat(0x7f0d78c96f37, {...}) = 0
[pid 22865] open(0x7f0d78d6d3e0, O_RDONLY|O_NONBLOCK) = 12
[pid 22865] fstat(12, {...})            = 0
[pid 22865] pread(12, 0x7f0d78ef0000, 8857, 0) = 8857
[pid 22865] writev(11, [?] 0x7ffc7958b660, 1) = 286
[pid 22865] sendfile(11, 12, 0x7ffc7958b658, 8857) = 8857
[pid 22865] write(4, 0x7f0d78efc000, 9811) = 9811
[pid 22865] close(12)                   = 0
[pid 22865] setsockopt(11, SOL_TCP, TCP_NODELAY, 0x7ffc7958bfac, 4) = 0
[pid 22865] recvfrom(11, "", 1024, 0, NULL, NULL) = 0
[pid 22865] write(5, 0x7ffc7958b030, 87) = 87
[pid 22865] close(11)                   = 0
[pid 22865] epoll_wait(9,  <unfinished ...>
[pid 22866] <... epoll_wait resumed> {}, 512, 100) = 0
[pid 22866] epoll_wait(11, {}, 512, 100) = 0
[pid 22866] epoll_wait(11, {}, 512, 100) = 0
[pid 22866] epoll_wait(11, {}, 512, 100) = 0
[pid 22866] epoll_wait(11, {}, 512, 100) = 0
...

(题外话: 这里还可以直观的看到 epoll 实质上是一个死循环)

简单解读一下，前面的 epoll，read，write 相关的代码应该都是从客户端获取请求，并且写入日志，然后注意到了 sendfile。先前了解过 sendfile，它提供了从一个文件描述符到另一个文件描述符的高效的复制数据的方式。传统的基于 read, write 的方式需要把数据在用户空间进行操作，而 sendfile 是直接在内核空间进行的操作，所以性能要好。这时候就想到的就是 Tengine / Nginx 其实是有一个配置也就是 Sendfile On; 来激活 sendfile 来提供静态文件的访问速度的，所以就想到可能问题就是在这里，遂尝试关闭。果然 curl 拿到的文件不再有末尾的乱码。

为什么

至此问题是解决了，但是我们还是要来探究一下到底是为什么 sendfile 在这种场合下就不工作了。有了关键词之后，问题就变得相对容易 Google 了。

首先找到了 Vargrant 也存在这个问题（因为默认也是基于 VirtualBox 的），并且在 Apache 和 NGINX 中都存在这个情况：

https://jeremyfelt.com/2013/01/08/clear-nginx-cache-in-vagrant/ https://github.com/mitchellh/vagrant/issues/351#issuecomment-1339640

然后就顺藤摸瓜的找到了 VirtualBox 的官方的 ticket：

https://www.virtualbox.org/ticket/12597

原来是 VirtualBox 的共享目录在使用 sendfile 来进行复制文件的时候，会错误的访问到缓存的内容导致的。看了下报告 bug 的时间已经是2年前，果然 VirtualBox 毕竟不是 Oracle 亲生的，这个问题并没有得到重视，暂时还是先只能通过关掉 sendfile 来解决这个问题。

经验总结

  1. strace 真的是神器，不用调试就可以让你看到程序运行的一些细节
  2. Bug 有可能发生在你用到的任何组件里，对于一个全新的环境要有足够的警惕性，不能想当然
欢迎关注我们的公众号