Docker 容器日誌分析

摘要： 先使用docker run -it --rm -d -p 80:80 nginx:1.15.8-alpine 命令啟動一個nginx容器。如果沒有異常，會得到容器ID如d2408a7931c95a3a83ffeca2fba887763cf925a67890ef3be4d9ff...

先使用docker run -it --rm -d -p 80:80 nginx:1.15.8-alpine 命令啟動一個nginx容器。如果沒有異常，會得到容器ID如d2408a7931c95a3a83ffeca2fba887763cf925a67890ef3be4d9ff838aa25b00 的長串。再使用curl -i http://127.0.0.1 訪問服務，確認nginx容器正常啟動執行。最後使用docker logs -f d24 檢視容器的日誌輸出，大概如下：

172.17.0.1 - - [24/Mar/2019:03:51:21 +0000] "GET / HTTP/1.1" 200 612 "-" "curl/7.29.0" "-"
複製程式碼

一般來說使用容器ID的前3位即可

以上就是我們檢視容器日誌的日常方法了，非常簡單實用。

容器日誌檔案儲存

容器的日誌會以json檔案方式儲存在本地磁碟，可以使用下面方式檢視檔案路徑docker inspect d42 | grep Log 可以找到:

"LogPath": "/var/lib/docker/containers/d2408a7931c95a3a83ffeca2fba887763cf925a67890ef3be4d9ff838aa25b00/d2408a7931c95a3a83ffeca2fba887763cf925a67890ef3be4d9ff838aa25b00-json.log",
複製程式碼

注意1：mac上沒有/var/lib/docker目錄 ，因為docker for mac的運作方式不一樣，最好使用linux系統練習。

注意2:如果LogPath內容為空，大概是因為docker engine版本，升級docker版本能到docker-ce 18.09.3

檢視d2408a7931c95a3a83ffeca2fba887763cf925a67890ef3be4d9ff838aa25b00-json.log 檔案，可以看到:

{"log":"172.17.0.1 - - [24/Mar/2019:03:51:21 +0000] \"GET / HTTP/1.1\" 200 612 \"-\" \"curl/7.29.0\" \"-\"\r\n","stream":"stdout","time":"2019-03-24T03:51:21.982476951Z"}
複製程式碼

這條資訊的log 欄位內容和之前通過docker logs 命令檢視的內容一致。

容器日誌會跟隨容器生命週期，容器銷燬後日志也會銷燬。使用docker stop 24 關停測試的nginx服務。因為容器啟動使用時候用了--rm 引數，關停後會自動清理刪除，所以會發現 /var/lib/docker/containers/d2408a7931c95a3a83ffeca2fba887763cf925a67890ef3be4d9ff838aa25b00目錄不存在了，相應的日誌檔案也就刪除了。

容器日誌檔案滾動策略

docker容器日誌預設寫入json檔案，在線上執行時候會有磁碟寫滿的風險。可以調整策略，讓其進行滾動。修改/etc/docker/daemon.json （如果沒有就手工建立一個），增加下面內容：

{
"log-opts": {
"max-size": "1m",
"max-file": "3"
}
}
複製程式碼

修改完成後重啟docker服務：

systemctl daemon-reload
systemctl restart docker.service
複製程式碼

測試一下新的日誌策略，使用下面的命令建立一個容器：

docker run -d --rm alpine:3.6 sh -c "while true; do echo hello world; usleep 10; done"
複製程式碼

這個alpine容器就是每隔10微秒輸出hello world，保持高頻度輸出，快速生產日誌檔案。

注：shell中的時間控制
1、sleep : 預設為秒。
sleep 1s 表示延遲一秒
sleep 1m 表示延遲一分鐘
sleep 1h 表示延遲一小時
sleep 1d 表示延遲一天

2、usleep : 預設以微秒。
1s = 1000ms = 1000000us
複製程式碼

按照前文中檢視日誌檔案的方法

# pwd
/var/lib/docker/containers/aa3307f5b42770319129e126122be123cfd8e0ebe1c412371ad27e62faa007e3
# ls -lah
total 2.6M
drwx------ 4 root root 4.0K Mar 24 16:22 .
drwx------ 3 root root 4.0K Mar 24 16:21 ..
-rw-r----- 1 root root 647K Mar 24 16:22 aa3307f5b42770319129e126122be123cfd8e0ebe1c412371ad27e62faa007e3-json.log
-rw-r----- 1 root root 977K Mar 24 16:22 aa3307f5b42770319129e126122be123cfd8e0ebe1c412371ad27e62faa007e3-json.log.1
-rw-r----- 1 root root 977K Mar 24 16:21 aa3307f5b42770319129e126122be123cfd8e0ebe1c412371ad27e62faa007e3-json.log.2
複製程式碼

很容易發現，日誌檔案的策略就是維持3個1m大小檔案存在，和我們設定保持一致。

測試完成後，記得使用docker stop aa3 清理測試現場，max-size也可以按照真實需求調整大小。

nginx容器日誌

瞭解docker容器的日誌策略後，再看看常用的容器是如何處理的。先看看nginx容器。

首先docker run -it --rm -d -p 80:80 nginx:1.15.8-alpine 建立一個nginx容器，然後docker exec -it b6d sh 進入容器，檢視/etc/nginx/nginx.conf可以看到下面內容：

error_log/var/log/nginx/error.log warn;
access_log/var/log/nginx/access.logmain;
複製程式碼

也就是nginx會將錯誤日誌和訪問日誌寫入對應的日誌檔案。繼續檢視/var/log/nginx目錄：

/var/log/nginx # ls -lah
total 0
drwxr-xr-x2 rootroot39 Mar4 07:54 .
drwxr-xr-x3 rootroot18 Mar4 07:54 ..
lrwxrwxrwx1 rootroot11 Jan 31 23:32 access.log -> /dev/stdout
lrwxrwxrwx1 rootroot11 Jan 31 23:32 error.log -> /dev/stderr
複製程式碼

這就發現奧祕了，access.log檔案會通過軟連結重定向到標準輸出，而錯誤日誌error.log則會重定向標準錯誤。這樣使用docker log 命令就可以看到nginx的訪問日誌了。

為了進一步驗證，檢視nginx dockerfile 檔案，其中有：

# forward request and error logs to docker log collector
&& ln -sf /dev/stdout /var/log/nginx/access.log \
&& ln -sf /dev/stderr /var/log/nginx/error.log
複製程式碼

可見nginx映象建立時候就定義好了日誌檔案的輸出。

同樣使用docker stop 524 清理現場，以後就不再介紹清理這一步驟了。

mysql容器日誌

啟動一個mysql容器

docker run --rm -e MYSQL_ROOT_PASSWORD=123456 mysql:5.7
複製程式碼

不難看到mysql容器日誌輸出, 擷取其中片段如下:

Initializing database
2019-03-24T08:48:19.102726Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2019-03-24T08:48:20.241459Z 0 [Warning] InnoDB: New log files created, LSN=45790
2019-03-24T08:48:20.414933Z 0 [Warning] InnoDB: Creating foreign key constraint system tables.
2019-03-24T08:48:20.509897Z 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 935a6ee7-4e11-11e9-b135-0242ac110002.
2019-03-24T08:48:20.519148Z 0 [Warning] Gtid table is not ready to be used. Table 'mysql.gtid_executed' cannot be opened.
2019-03-24T08:48:20.519843Z 1 [Warning] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2019-03-24T08:48:24.066683Z 1 [Warning] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode.
2019-03-24T08:48:24.066730Z 1 [Warning] 'user' entry 'mysql.session@localhost' ignored in --skip-name-resolve mode.
2019-03-24T08:48:24.066740Z 1 [Warning] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode.
2019-03-24T08:48:24.066756Z 1 [Warning] 'db' entry 'performance_schema mysql.session@localhost' ignored in --skip-name-resolve mode.
2019-03-24T08:48:24.066761Z 1 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
2019-03-24T08:48:24.066772Z 1 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
2019-03-24T08:48:24.066814Z 1 [Warning] 'tables_priv' entry 'user mysql.session@localhost' ignored in --skip-name-resolve mode.
2019-03-24T08:48:24.066822Z 1 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
Database initialized
Initializing certificates
Generating a RSA private key
複製程式碼

檢視mysqlDockerfile 檔案，可以知道mysql映象啟動入口在entrypoint.sh ，從指令碼中發現：

echo 'Initializing database'
"$@" --initialize-insecure
echo 'Database initialized'
複製程式碼

這樣就是mysql容器啟動時候的輸出對應起來了。entrypoint.sh 比較複雜，主要功能就是啟動mysqld，並將日誌輸出，因為不是本文重點，就不詳細介紹了。