记一次 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 有可能发生在你用到的任何组件里，对于一个全新的环境要有足够的警戒性，不能想固然