記一次 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 有可能發生在你用到的任何組件裏，對於一個全新的環境要有足夠的警戒性，不能想固然