摘要：最近在公司搭建一個(gè)基于的環(huán)境。的內(nèi)核可以算是半個(gè)，依賴一些的容器相關(guān)的技術(shù)是不支持的，所以需要通過一個(gè)虛擬機(jī)運(yùn)行來使用。于是和前端的同學(xué)，一起打開文件進(jìn)行對(duì)比，但并沒有發(fā)現(xiàn)非常可疑的點(diǎn)。果然拿到的文件不再有末尾的亂碼。

最近在公司搭建一個(gè)基于 Docker 的 PHP 環(huán)境。

Docker 是一種容器技術(shù)，它可以提供一個(gè)隔離的環(huán)境，讓用戶的程序運(yùn)行在一個(gè)完全隔離的虛擬的系統(tǒng)里，但 Docker 不是虛擬化，使用 Docker 可以在 Linux 上實(shí)現(xiàn)對(duì)于任意程序打包一次，到處運(yùn)行。愿意接受安利的同學(xué)請(qǐng)移步 http://docker.io 。

Mac OS X 的內(nèi)核可以算是半個(gè) BSD，Docker 依賴一些的 Linux 容器相關(guān)的技術(shù)是 OS X 不支持的，所以需要通過一個(gè)虛擬機(jī)運(yùn)行 Linux 來使用。

Docker 官方提供了一個(gè)方便 OS X 用戶的名為 "dockertoolbox" 的軟件包，包括這些內(nèi)容：Docker CLI 客戶端 + Docker Machine CLI 管理界面 + Docker 倉(cāng)庫(kù) + VirtualBox + CoreOS + Kitematic （一個(gè)管理容器的GUI界面）。其中 CoreOS 是專門為虛擬化和容器技術(shù)設(shè)計(jì)的一個(gè) Linux 發(fā)行版，精簡(jiǎn)到了只剩容器和虛擬化需要的一些組件，所以性能非常好。

因?yàn)榇罱?Docker PHP 環(huán)境的需要，已經(jīng)把自己日常的業(yè)務(wù)開發(fā)遷移到了 Docker 上。如同往常一樣 git pull 拉下最新代碼，然后用瀏覽器打開正在開發(fā)中的項(xiàng)目，發(fā)現(xiàn)頁(yè)面上一片空白了，打開 Chrome 的控制臺(tái)，出現(xiàn) Javascript 相關(guān)的報(bào)錯(cuò)，并且在文件底部發(fā)現(xiàn)一連串的亂碼：

?????????????????

用 curl 拉下來然后用 vim 打開如下：

想當(dāng)然的認(rèn)為這可能是前端的鍋。于是和前端的同學(xué)，一起打開文件進(jìn)行對(duì)比，但并沒有發(fā)現(xiàn)非?？梢傻狞c(diǎn)。然后就覺得是 Tengine 產(chǎn)生的問題，因?yàn)榍袚Q到自己的真實(shí)的宿主機(jī)用 Nginx 1.8.0 訪問，沒有這個(gè)問題。切換到 Docker 的環(huán)境就有這個(gè)問題，而兩者的配置又幾乎是一樣的。

為了驗(yàn)證是否是 Tengine 產(chǎn)生的問題，在 Docker 容器中依次安裝了 Tengine 2.1.2 (最新版), Nginx 1.9.10 (最新版), Nginx 1.8.0 (和宿主機(jī)相同)，均采用同一配置文件進(jìn)行啟動(dòng)，然而無一幸免的都還是出現(xiàn)了這個(gè)問題。

用排除法的話就可以認(rèn)為問題可能在網(wǎng)絡(luò)通信或者是容器本體上了，嘗試先排除網(wǎng)絡(luò)的影響。繞過網(wǎng)絡(luò)的映射，直接在 Docker 的容器內(nèi)部使用 curl 訪問來檢查，發(fā)現(xiàn)仍然存在這個(gè)問題，所以問題基本可以限定在容器上面。

為了驗(yàn)證到底是不是容器產(chǎn)生的問題，在運(yùn)維同學(xué)的建議下，第二天在虛擬機(jī)中特意安裝了一個(gè) CentOS 6.7，以及安裝上公司運(yùn)維組預(yù)編譯的 PHP 和 Tengine 的 RPM 包，然后采用完全一樣的配置，再次用 curl 訪問同樣的文件，沒有觀察到這個(gè)現(xiàn)象。所以確實(shí)可以確定已經(jīng)是容器產(chǎn)生的問題。

盡管這里幾乎已經(jīng)確定問題是哪里產(chǎn)生的，仍然陷入了死胡同，想要 Google 也不知道到底用什么關(guān)鍵詞。這個(gè)時(shí)候再試著在 Tengine 的日志中輸出的 HTTP Response 的消息體給記錄下來，在 Tengine 的配置中加上了這些代碼，用 Lua 來獲取 HTTP 的 Response，并記錄進(jìn)日志：

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 {} 區(qū)域

  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函數(shù)的截取長(zhǎng)度，可以按需要改大點(diǎn)
    ngx.ctx.buffered = (ngx.ctx.buffered or "") .. resp_body
    if ngx.arg[2] then
      ngx.var.resp_body = ngx.ctx.buffered
    end
  ";
# 上面的配置加入 server {} 區(qū)域
# 然后開啟對(duì)應(yīng)的 access_log 即可

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

不過遺憾的是，訪問日志里面并沒有出現(xiàn)亂碼，而在 curl 的結(jié)果中，亂碼又確實(shí)還是存在的。

事已至此，想到可能需要對(duì) Tengine 或者 Nginx 調(diào)試一下可能才能發(fā)現(xiàn)到底問題是出在什么地方了。所以想到了曾經(jīng)跟蹤一個(gè) PHP 的 Segmentation Fault 時(shí)用過的 strace，它可以打印出一個(gè)進(jìn)程的所有的系統(tǒng)調(diào)用(System Call)，從而觀察程序大致上做了一些什么事情。于是馬上安裝上 strace，用帶 -f 的參數(shù)來運(yùn)行 Tengine。

strace -f tengine

(# -f 參數(shù)是 follow forks，因?yàn)?Tengine / NGINX 的實(shí)際接受用戶請(qǐng)求的 Worker 是 fork 新建的進(jìn)程)

然后照常用 curl 進(jìn)行請(qǐng)求，獲得輸出：

...
[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,  
[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,  
[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 實(shí)質(zhì)上是一個(gè)死循環(huán))

簡(jiǎn)單解讀一下，前面的 epoll，read，write 相關(guān)的代碼應(yīng)該都是從客戶端獲取請(qǐng)求，并且寫入日志，然后注意到了 sendfile。先前了解過 sendfile，它提供了從一個(gè)文件描述符到另一個(gè)文件描述符的高效的復(fù)制數(shù)據(jù)的方式。傳統(tǒng)的基于 read, write 的方式需要把數(shù)據(jù)在用戶空間進(jìn)行操作，而 sendfile 是直接在內(nèi)核空間進(jìn)行的操作，所以性能要好。這時(shí)候就想到的就是 Tengine / Nginx 其實(shí)是有一個(gè)配置也就是 Sendfile On; 來激活 sendfile 來提供靜態(tài)文件的訪問速度的，所以就想到可能問題就是在這里，遂嘗試關(guān)閉。果然 curl 拿到的文件不再有末尾的亂碼。

至此問題是解決了，但是我們還是要來探究一下到底是為什么 sendfile 在這種場(chǎng)合下就不工作了。有了關(guān)鍵詞之后，問題就變得相對(duì)容易 Google 了。

首先找到了 Vargrant 也存在這個(gè)問題（因?yàn)槟J(rèn)也是基于 VirtualBox 的），并且在 Apache 和 NGINX 中都存在這個(gè)情況：

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 來進(jìn)行復(fù)制文件的時(shí)候，會(huì)錯(cuò)誤的訪問到緩存的內(nèi)容導(dǎo)致的?？戳讼聢?bào)告 bug 的時(shí)間已經(jīng)是2年前，果然 VirtualBox 畢竟不是 Oracle 親生的，這個(gè)問題并沒有得到重視，暫時(shí)還是先只能通過關(guān)掉 sendfile 來解決這個(gè)問題。

strace 真的是神器，不用調(diào)試就可以讓你看到程序運(yùn)行的一些細(xì)節(jié)

Bug 有可能發(fā)生在你用到的任何組件里，對(duì)于一個(gè)全新的環(huán)境要有足夠的警惕性，不能想當(dāng)然