NginxでHTTPヘッダのログをとる

Search Consoleのフォーラムで、WordPressのGoogle XML Sitemapsプラグインで出力したサイトマップをSearch Consoleで登録しようとすると受け付けてくれないという話題が出ていた。 自分のところでは何の問題もないのでプラグインが悪いのかGoogleが悪いのか、ウェブサーバの応答が遅いからとか別に問題があるのかよくわからない。
ところで、Search Consoleにサイトマップを登録する際に、確認のためにGoogleのクローラーがサイトを訪れるのだが、どのような遣り取りをするのかしら?(古めのChromeが来るのと同じというように聞いてたけど)
あいにく、手持ちのすべてのサイトがSSL対応になっているのでパケットキャプチャで通信を見るというのは無理。
そこでウェブサーバのログを見ることにした。普通のアクセスログだけでは何もわからないのでHTTPヘッダ周り、リクエストとレスポンス部分。

その前に、ウェブサイトにGoogleではない普通のブラウザでアクセスしたのと似た状態で遣り取りを見る。これはcurlで簡単に見ることができる。

sitemap.xmlをリクエストしてsitemap.xml.gzが返されることを期待して、curlのオプションとしてクライアント側がgzip圧縮のエンコーディングに対応しているという通知を付ける。もっと今時のブラウザっぽくならgzip, deflate, brの3種類を指定する。

% curl -H "Accept-Encoding: gzip" -v https://gato.intaa.net/sitemap.xml
*   Trying 2001:2c0:d800:6701::3000...
* TCP_NODELAY set
* Connected to gato.intaa.net (2001:2c0:d800:6701::3000) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /usr/local/share/certs/ca-root-nss.crt
  CApath: none
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
*  subject: CN=gato.intaa.net
*  start date: May 25 18:50:54 2019 GMT
*  expire date: Aug 23 18:50:54 2019 GMT
*  subjectAltName: host "gato.intaa.net" matched cert's "gato.intaa.net"
*  issuer: C=US; O=Let's Encrypt; CN=Let's Encrypt Authority X3
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x800b8d000)
> GET /sitemap.xml HTTP/2
> Host: gato.intaa.net
> User-Agent: curl/7.64.1
> Accept: */*
> Accept-Encoding: gzip
> 
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
* Connection state changed (MAX_CONCURRENT_STREAMS == 128)!
< HTTP/2 200 
< server: nginx
< date: Thu, 06 Jun 2019 12:30:55 GMT
< content-type: text/xml; charset=utf-8
< x-robots-tag: noindex
< content-encoding: gzip
< vary: Accept-Encoding
< strict-transport-security: max-age=31536000;
< access-control-allow-credentials: true
< x-content-type-options: nosniff always
< content-security-policy: default-src * 'self' data: 'unsafe-inline' 'unsafe-eval'; child-src * 'self';

行頭が > がリクエストヘッダ。行頭が < が応答側でレスポンスヘッダ・エンティティヘッダ。

サーバーから返されるHTTPヘッダだけ見たいなら-Iオプションを付けて-vオプションを除く。
% curl -I -H "Accept-Encoding: gzip" https://gato.intaa.net/sitemap.xml
HTTP/2 200 
server: nginx
date: Thu, 06 Jun 2019 06:45:47 GMT
content-type: text/xml; charset=utf-8
x-robots-tag: noindex
content-encoding: gzip
vary: Accept-Encoding
strict-transport-security: max-age=31536000;
access-control-allow-credentials: true
x-content-type-options: nosniff always
content-security-policy: default-src * 'self' data: 'unsafe-inline' 'unsafe-eval'; child-src * 'self';

gzipによる圧縮を受け入れ可能だという条件付きでsitemap.xmlを要求しているので、ウェブサーバ側はcontent-encoding: gzipであると返答してsitemap.xmlではなくsitemap.xml.gzを渡す。(ただし上のcurlコマンドではバイナリファイルのダウンロードは保留される)

ブラウザでHTTPヘッダを確認する
curlコマンドではなく、ブラウザでも確認できる。上の画像はChromeブラウザだがFirefoxでもほぼ同じ。
目的のページを表示する。(今回はサイトのsitemap.xml)
[F12]を押して検証・開発者用窓を開く。
タブから「Network」を選択する。
ページを再表示する(重要)
目的のページやその構成ファイルなどを1つ選択する。
右列上部の「Headers」タブを選択する。
右列下部にリクエストヘッダとレスポンスヘッダが表示される。

このように、自分側のcurlとウェブサーバの通信は見るのは簡単だが、クローラー(や他所からのビジター)とウェブサーバの通信はSSLだとパケットキャプチャしても基本的には内容がわからない。
そこで、ウェブサーバ(Nginx)にHTTPヘッダ関係のログを取る設定を追加する。先のcurlで見たような通信時に送った・送られた全てのリクエストヘッダ・レスポンスヘッダ・エンティティヘッダが得られるわけではないが、取得したい内容を指定することである程度の情報は取得できる。

/usr/local/etc/nginx/nginx.conf (Nginxのメインの設定)
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
http {

    log_format  main   '既存のまま';

    log_format  ssl    '既存のまま';

    log_format  header  '[$time_local] '
                        'host: $remote_addr\t'
                        'user: $remote_user\t'
                        'request: $request\t'
                        'status: $status\t'
                        'size: $body_bytes_sent\t'
                        'referer: $http_referer\t'
                        'http_host: $http_host\t'
                        'request_time: $request_time\t'
                        'content_type: $sent_http_content_type\t'
                        'accept_encoding: $http_accept_encoding\t'
                        'accept_language: $http_accept_language\t'
                        'user_agent: $http_user_agent\t';           

    その他の指定

    include /usr/local/etc/nginx/Includes/*.conf;   #vHostの設定ファイル読み込みを想定
}

ログとして取得する内容の内、上の例ではリクエストヘッダ・レスポンスヘッダ・エンティティヘッダが混ざってる。スミマセン。
もちろん、これだけしか取れないというわけではないので欲しい情報があれば項目を足したり不要な情報の項目を消したり。

/usr/local/etc/nginx/Includes/hoge.conf (Nginxの或るバーチャルホストの設定部分)
1
2
3
4
5
6
7
8
9
server {

    #ログファイル指定部分
    access_log /var/log/hoge-access.log;   #これはmain
    access_log /var/log/hoge-ssl.log ssl;     #ssl
    access_log /var/log/hoge-header.log header;  #←今回追加分header

    その他の指定
}
ログには下のように記録される。(これはChromeブラウザからのアクセス) [06/Jun/2019:11:17:27 +0900] host: ***.***.***.*** user: - request: GET /test.html HTTP/2.0 status: 200 size: 3078 referer: - http_host: hoge.example.com request_time: 0.097 content_type: text/html; charset=UTF-8 accept_encoding: gzip, deflate, br accept_language: ja,ja-JP;q=0.9,en-US;q=0.8,en;q=0.7 user_agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/75.0.3770.80 Safari/537.36

Search Consoleでサイトマップを登録しようとしたときにやってくるクローラーのアクセスは下のようなの。(わかりやすいように項目別に改行した。)

[06/Jun/2019:10:44:37 +0900]
host: 66.249.79.81
user: -
request: GET /sitemap.xml HTTP/1.1
status: 200
size: 640
referer: -
http_host: hoge.example.com
request_time: 0.100
content_type: text/xml;charset=utf-8
accept_encoding: gzip,deflate,br
accept_language: -
user_agent: Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)

上の例ではヘッダフィールドの種類が混じっているので判りにくいが、欲しい値だけを書くとこうなった。真面目な人は混ぜずにきっちり設定して欲しい。
http_hostはウェブサーバ側のホスト名このページではhoge.example.com(仮名)に書き換えている。
http_accept_encodingがgzip, delfate, brになっているのでbrotli圧縮にも対応してたのね。

通常の運用時にはHTTPヘッダのログなんて取る必要がないのでこのページの設定は無効にしておく。