【Squid FAQ】 最終更新日：2005年11月1日

6. Squidのログファイル

squidのログは、動作状況の貴重な情報源です。　アクセス記録以外にもシステムエラーやリソースに関する情報なども記録されます。　
Squidのログ解析に関しては最初にこちらを読んで頂いた方が良いかもしれません。

6.1 squid.out

もしSquidをRunCacheスクリプトから起動すると、Squidの実行状況がここに記録されます。　もし、SquidがエラーとなってRunCacheによって再起動された場合にはその痕跡が残ります。

6.2 cache.log

cache.logはSquidによって生成され、エラーやデバックメッセージが記録されます。　もしRunCacheスクリプトか-sオプションを付けてSquidを起動したなら、syslogの情報も記録されることでしょう。syslogとして何が出力されるかは

6.3 store.log

store.logには、キャッシュに記録されたもしくは削除されたオブジェクトの記録が残ります。　また、どんな情報にどれだけアクセスされたのかの調査にも利用できます。

このログファイルの記録内容は、1行で１エントリを表し、1行はスペースでセパレートされた11項目であらわされます。　11項目はsec/store_log.cの中の storeLog() 関数で定義されています。内容は

"%9d.%03d %-7s %08X %4d %9d %9d %9d %s %d/%d %s %s\n"

となっており順に、

• time
  ミリ秒であらわされるUTC時間（1970/1/1を基点とした時間）です。
  
• action
  オブジェクトのストア状態を報告します。
  
  ・CREATE ： 存在しなかったので作成されたようです。
  ・RELEASE ： キャッシュから開放されたようです。
  ・SWAPOUT ： オブジェクトはディスクに退避されました。
  ・SWAPIN ： ディスクにあるオブジェクトをキャッシュへロードしました。
  
• file number
  file numberはオブジェクト格納ファイルを表している。　設定のcache_dir で指定されたディレクトリパスの中のファイルを示す値となる。
  
  file numberが FFFFFFFF のものは、メモリのみに存在するオブジェクトである。いくつかのactionコードでは、このようなメモリオブジェクトを参照します。例えばRELEASEアクションではメモリオブジェクトから開放されるため、file number はFFFFFFFF となります。
  
• status
  HTTPの応答コードです。
  
• datehdr
  これは、HTTPの応答ヘッダーの"Date:"の値です。
  
• lastmod
  これは、HTTPの応答ヘッダーの"Last-Modified"（最終変更日？）の値です。
  
• expires
  これは、HTTPの応答ヘッダーの"Expires:"（保存期間？）の値です。
  
• type
  HTTPの"Content-Type"を返します。　判らないときは"unknown"を返します。
  
• sizes
  ここにはスラッシュで区切られた２つの値が入ります。
  
  1.HTTPの応答ヘッダーの"Content-Length: "の値。
  2.実際に読み取った値。
  
• method
  オブジェクトへのリクエストメソッド。 例えばGET。
  
• key
  オブジェクトへのキー、通常はURL。
  

6.4 hierarchy.log

これはsquid1.0だけのためにあるログファイルです。フォーマットは

[date] URL peerstatus peerhost

となっています。

6.5 access.log

殆どのアクセス解析プログラムは、access.logを調べることで可能です。squidではaccess.logとして２つの形式をサポートしています。１つは"emulate_httpd_log "オプションを使うことでhttpd互換（CERN web daemon互換：common log file format（CLF）と言います）のフォーマットを、もうひとつはsquid本来のログ形式をサポートしています。

common log fileフォーマットは、squid本来のlogフォーマットに比べ多くの情報を持ち、かつ、ログファイルとしては小さくなります。　squid本来のログには管理者のためにキャッシュ評価に関する情報が多く含まれます。

common log fileのフォーマット

common log fileフォーマットは多くのhttpサーバで利用されています。　このファイルは７のフィールドによって構成されます。

remotehost rfc931 authuser [date] "method URL" status bytes

common log fileのフォーマットは多様なツールで利用できます。　またこのフォーマットには、HTTPのバージョンのようにsquid本来のログと異なる情報を含みます。　

squid本来のlogフォーマット（ネイティブフォーマット）

squid本来のlogフォーマットはsquidのバージョンによって形式が異なります。squid1.0では、

time elapsed remotehost code/status/peerstatus bytes method URL

squid1.1からは、階層に関する情報がhierarchy.logからaccess.logに移されました。結果ログの形式は、

time elapsed remotehost code/status bytes method URL rfc931 peerstatus/peerhost type

squid2.0では、同じ形式を使っています。

CLFとsquid独自のログの違いは、リクエスト継続時間・タイムアウト情報・上流サーバアドレス・コンテンツタイプなどです。

squid2common.pl はCERN プロキシ形式のログフォーマットへの変換ツールです。この形式にすることで、多くの分析ツールの利用が可能になります。

access.logネイティブフォーマットの細部

squidのネイティブログを利用することで、多くの情報を解析できることでしょう。ネイティブフォーマットは次のような構成になっています。

"%9d.%03d %6d %s %s/%03d %d %s %s %s %s%s/%s %s"

これは順に、

• time
  ミリ秒で示されるUTC時間（1970年1月1日を基点の時間）です。これは以下の perl スクリプトで読みやすい時間に変換できます。

#! /usr/bin/perl -p s/^\d+\.\d+/localtime $&/e;

上記のスクリプト適当な名前で作成して、chmodで実行属性を付けた後、squidのログを標準入力で与えて実行させればログの時間が変換されます。

• duration
  キャッシュから読み出すのみ必要とした時間をミリ秒で表します。これはTCPｔｐUDPでは解釈の仕方が異なります。
  
  • HTTP/1.0ではaccept() からcllose()までの時間です。
  • 持続性のある接続ではスケジューリングから応答が終了するまでの経過時間です。
  • ICPにおいてはスケジューリングから応答が終了するまでの経過時間です。

これらがログに記録されるのは応答が終了してからという点に注意してください。

• client address
  リクエストしてきたクライアントのIPアドレスです。　
  log_fqdnオプションを設定ファイルで指定することで、ログのアドレスはFQDN(完全修飾名）で記録されるようになりますが、パフォーマンスには影響を与えます。
  
• result codes
  結果を知らせます。これはスラッシュで２つの内容で構成されています。　
  
  1. キャッシュへの要求の結果。　
     キャッシュへの要求の結果のコードが返されます。　これで例えばキャッシュがヒットしたのか失敗したのかわかります。コードの意味についてはこちら。
     いくつかのコードは古いバージョンのもので、今では使われなくなっています。　特にERR_* に関してはこれ以上記録されることはありません。
  2. 状況部分。
     状況部分にはHTTPでの詳細結果やRFCで定義されているコードを記録します。状況コードに関してはこちら。

• byte
  クライアントへ渡された総バイト数です。ヘッダーを含めたサイズですので、表示されるオブジェクトのバイト数でないことに気を付けてください。　エラーページの表示では、当然そのサイズが記録されます。
  
• request method（リクエストメソッド）
  オブジェクトを得るための要求です。　これについてはここを参照してください。 設定ファイルでlog_icp_queriesをOFFにしたなら、ICP exchangesの情報は記録されません。 また、設定ファイルACLの記述で、"method purge"をenableにしたときのみ、PURGEメソッドは記録されます。
  
• URL
  リクエストされたURLが記録されます。　URLには空白が記録されることがあるので注意してください。　ただし設定ファイルでuri_whitespaceを無効にしているので、デフォルトでは空白のURLは拒否しています。
  
• rfc931
  リクエストしたクライアントのident lookupを記録します。　パフォーマンスに影響を与えるため、デフォルトでは設定ファイルでident_loookups offとしているので記録されません。単に"-"がひとつ記録されていることでしょう。
  
• hierarchy code（階層コード）
  階層コードは３つのパターンがあります。
  
  1. ICPリクエストがタイムアウトになったなったような場合には、常にTIMEOUT_という接頭語付けたログが残ります。　
  2. どのように要求を処理したかの記録が残ります。　例えばpeerサーバに転送したとか、直接サーバへアクセスしたとか。　階層コードやリムーブコードの詳細についてはこちら。
  3. リクエストをフォワードした際のIPアドレスまたはホスト名。　これは起源サーバのアドレスです。これは隣接のキャッシュサーバのアドレスです。。
  
  
• type
  HTTPヘッダーにリプライされてきたオブジェクトのコンテンツタイプです。　ICPのキャッシュ交換の場合にはここは"-"になることに留意してください。またいいくつかの奇妙なリプライには":"や空白を記録します。

6.6 useragent.log

ユーザエージェントログは、維持されているだけのファイルです。　

1. コンパイル時に--enable-useragent-log オプションをつけてコンパルイルし、かつ、
2. 設定ファイルで、"useragent_log"を使うように設定した時

のために用意されています。これによって、ユーザが利用しているブラウザのディストリビューション名を得ることができます。
このオプションはSquidの中に統合すべきではないアイデアかもしれない。

6.7 Squid result codes （リザルトコード）

HTTPへのリクエストはTCP_として、ICPへのリクエストにはUDP_として結果コードを記録します。ICPのログをとらないなら、設定ファイルで、log_icp_queriesを無効にしなさい。
以下のリザルトコードは、Squid-2でのものです。

• TCP_HIT
  要求されたオブジェクトのコピーがキャッシュにありました。
  
• TCP_MISS
  要求されたオブジェクトのコピーがキャッシュにありませんでした。
  
• TCP_REFRESH_HIT
  要求されたオブジェクトはキャッシュありました。しかし新鮮ではありませんでしたので"304 not modified"を返しました。
  
• TCP_REF_FAIL_HIT
  要求されたオブジェクトはキャッシュありました。しかし新鮮ではありませんでしたのでクエリはエラーとして、新鮮でないオブジェクトと一緒に返しました。
  
• TCP_REFRESH_MISS
  リクエストされたオブジェクトは新鮮ではなく、新しいコンテンツを返しました。
  
• TCP_CLIENT_REFRESH_MISS
  The client issued a "no-cache" pragma, or some analogous cache control command along with the request. Thus, the cache has to refetch the object.
  
• TCP_IMS_HIT
  クライアントは、キャッシュと新しいオブジェクトのIMS要求を出しました。
  
• TCP_SWAPFAIL_MISS
  オブジェクトはキャッシュにあるようですが、アクセスすることができませんでした。
  
• TCP_NEGATIVE_HIT
  ネガティブなオブジェクトへのリクエストです。例えば”404 not found”みたいな。
  
• TCP_MEM_HIT
  要求されたオブジェクトはキャッシュされており、しかもメモリにありました。　ディスクへのアクセスは行いません。
  
• TCP_DENIED
  このアクセス要求は拒否されました。
  
• TCP_OFFLINE_HIT
  オブジェクトはオフラインモードのキャッシュから取り出されました。　オフラインモードの方法は、設定ファイルsquid.confのoffline_modeを見てください。
  
• UDP_HIT
  要求されたオブジェクトの妥当なコピーがキャッシュにありました。
  
• UDP_MISS
  要求されたオブジェクトはこのキャッシュにありませんでした。
  
• UDP_DENIED
  要求されたアクセスは拒否されました。
  
• UDP_INVALID
  無効な要求を受け付けました。
  
• UDP_MISS_NOFETCH
  "-Y"オプションを指定して起動または、障害を起こしている間にキャッシュにヒットしたものは、UDP_HITまはたこのコードを返すことでしょう。
  
• NONE
  エラーの場合と、キャッシュマネージャリクエストの場合に記録されます。
  

以下のコードは、Squid-2でもはや利用できません:

• ERR_*
  エラーは今ではステータスコードに含まれます。
  
• TCP_CLIENT_REFRESH
  TCP_CLIENT_REFRESH_MISSを見てください。
  
• TCP_SWAPFAIL
  TCP_SWAPFAIL_MISSを見てください。
  
• TCP_IMS_MISS
  削除されました。　代りにTCP_IMS_HITが使われています。
  
• UDP_HIT_OBJ
  ヒットオブジェクトのログはもはや利用できません。
  
• UDP_RELOADING
  UDP_MISS_NOFETCHを見てください。
  

6.8 HTTP status codes （ステータスコード）

Squid-2ではRFC2616の内、307（Temporary Redirect），416 (Request Range Not Satisfiable)，417 (Expectation Failed)を除く殆どのコードが使われます。拡張用コードの0と600も無効なヘッダーやプロキシエラーの際に使います。またWebDAVの為のRFC2518のためのコードも返されます。　

000 Used mostly with UDP traffic.

100 Continue
101 Switching Protocols
*102 Processing

200 OK
201 Created
202 Accepted
203 Non-Authoritative Information
204 No Content
205 Reset Content
206 Partial Content
*207 Multi Status

300 Multiple Choices
301 Moved Permanently
302 Moved Temporarily
303 See Other
304 Not Modified
305 Use Proxy
[307 Temporary Redirect]

400 Bad Request
401 Unauthorized
402 Payment Required
403 Forbidden
404 Not Found
405 Method Not Allowed
406 Not Acceptable
407 Proxy Authentication Required
408 Request Timeout
409 Conflict
410 Gone
411 Length Required
412 Precondition Failed
413 Request Entity Too Large
414 Request URI Too Large
415 Unsupported Media Type
[416 Request Range Not Satisfiable]
[417 Expectation Failed]
*424 Locked
*424 Failed Dependency
*433 Unprocessable Entity

500 Internal Server Error
501 Not Implemented
502 Bad Gateway
503 Service Unavailable
504 Gateway Timeout
505 HTTP Version Not Supported
*507 Insufficient Storage

600 Squid header parsing error

6.9 Request methods （リクエストメソッド）

SquidはRFC2616で認められた幾つかのリクエストについて認めます。　Squid2.2-STABLE5以上では、WevDAVの拡張によるRFC2518の拡張も認めます。

method defined cachabil. meaning
------ ------ ------ -------------------------------------------
GET HTTP/0.9 possibly object retrieval and simple searches.
HEAD HTTP/1.0 possibly metadata retrieval.
POST HTTP/1.0 CC or Exp. submit data (to a program).
PUT HTTP/1.1 never upload data (e.g. to a file).
DELETE HTTP/1.1 never remove resource (e.g. file).
TRACE HTTP/1.1 never appl. layer trace of request route.
OPTIONS HTTP/1.1 never request available comm. options.
CONNECT HTTP/1.1r3 never tunnel SSL connection.

ICP_QUERY Squid never used for ICP based exchanges.
PURGE Squid never remove object from cache.

PROPFIND rfc2518 ? retrieve properties of an object.
PROPATCH rfc2518 ? change properties of an object.
MKCOL rfc2518 never create a new collection.
COPY rfc2518 never create a duplicate of src in dst.
MOVE rfc2518 never atomically move src to dst.
LOCK rfc2518 never lock an object against modifications.
UNLOCK rfc2518 never unlock an object.

6.10 Hierarchy Codes（階層コード）

Squid-2では以下の階層コードが使われます。

• NONE
  TCP Hit， TCP failures，cachemgr リクエスト，それとすべてのUDPリクエストの場合に記録されます。これらは階層に関する情報がありません。
  
• DIRECT
  オブジェクトはソースのサーバから入手されました。
  
• SIBLING_HIT
  オブジェクトはUDP_HITでで応じた兄弟サーバから入手されました。
  
• PARENT_HIT
  オブジェクトはUDP_HITでで応じた親サーバから入手されました。
  
• DEFAULT_PARENT
  ICPリクエストは送られませんでした。設定ファイルで"default"とされていた親が選ばれました。
  
• SINGLE_PARENT
  オブジェクトは、与えられたURLに適した親から入手されました。
  
• FIRST_UP_PARENT
  オブジェクトは親リストの最初の親から入手されました。
  
• FIRST_UP_PARENT
  おぬジェクトは、URLの為の親がいなかったので、ソースのサーバからダイレクトに入手されました。
  
• FIRST_PARENT_MISS
  オブジェクトは（多分、負荷のせいで）もっとも早く反応した親から返されました。
  
• CLOSEST_PARENT_MISS
  この親サーバが、ソースサーバまでのもっとも小さいRTTをもっていたので選ばれました。設定ファイルのclosests-only peerを参照してください。
  
• CLOSEST_PARENT
  親の選択は、自分のRTT測定に基づきました。
  
• CLOSEST_DIRECT
  自身のRTT測定の結果がどんな親より早いでした。
  
• NO_DIRECT_FAIL
  オブジェクトはファイヤーウォールの構成のために返されませんでした。
  
• SOURCE_FASTEST
  PINGにもっとも早く反応したので、ソースサーバが選ばれました。
  
• ROUNDROBIN_PARENT
  設定ファイルでラウンドロビンとして設定してあった親から、もっとも回数の少ないのを選びICPの返事を受け取りました。
  
• CACHE_DIGEST_HIT
  The peer was chosen, because the cache digest predicted a hit. This option was later replaced in order to distinguish between parents and siblings
  
• CD_PARENT_HIT
  キャッシュダイジェストによりオブジェクトヒットを予告されたので、この親が選ばれました。
  
• CD_SIBLING_HIT
  キャッシュダイジェストによりオブジェクトヒットを予告されたので、この兄弟が選ばれました。
  
• NO_CACHE_DIGEST_DIRECT
  このアウトプットは使われていないようですが？
  
• CARP
  ピアはCARPによって選ばれました。
  
• ANY_PARENT
  src/peer_select.c:hier_strings[]の部分。
  
• INVALID CODE
  src/peer_select.c:hier_strings[]の部分。
  

以下の階層コードはSquid-2からは除外されました。

code meaning
-------------------- -------------------------------------------------
PARENT_UDP_HIT_OBJ hit objects are not longer available.
SIBLING_UDP_HIT_OBJ hit objects are not longer available.
SSL_PARENT_MISS SSL can now be handled by squid.
FIREWALL_IP_DIRECT No special logging for hosts inside the firewall.
LOCAL_IP_DIRECT No special logging for local networks.

6.11 cache/log (Squid-1.x)

このファイルは不適切な名前を持っています。　これはswap logと呼ばれるべきものでディスクに書き込まれたオブジェクトの記録です。Squidのスタート時にリロードされます。もしSquidが動いていないときにこのファイルをリムーブすれば、キャッシュコンテンツの中をきれいにできます。Squidは新たにこのファイルを作り出します。　もっとも簡単な方法は、プロセスを次のように、

% squid -k shutdown

としてシャットダウンしてから、

% squid -k rotate

として、ログのローテーションをしてしまうと良いでしょう。Squid-1.1のログには６つの項目が記録されます。

• fileno ： オブジェクトを保持しているスワップファイルのファイルナンバー。　ファイルシステムのパスとしてマップされています。
• timestamp ： 最後に最新として確認されたオブジェクトのタイムスタンプ。　時間はUNIX時間（1970/1/1基点）の16進表記です。
• expires: ： HTTP応答ヘッダーに示されていたExpire（廃棄時間）の値です。　時にはExpireを返してこないヘッダーもありますので、その場合には-2またはfffffffeとします。　不正なヘッダだった場合には-1またはffffffffを記録します。
• lastmod ： HTTPヘッダーが返してきた、"Last-Modified（最終変更日）"の値です。　知らせてこなかった場合には-2を、不正なヘッダーの場合には-1を記録します。
• size ： ヘッダーを含んだオブジェクトのサイズです。
• url ： オブジェクトのURLです。

6.12 swap.state (Squid-2.x)

Squid-2からは、スワップログファイルは swap.state と呼んでいます。これはMD5によるチェックサムを含むバイナリファイルです。ファイルと内容に関する詳しくは、プログラマーガイドをご覧ください。
Squidが動作中にもし、swap.stateファイルを削除したければ、Squidにログローテーションのシグナルを渡してください。

% squid -k rotate

この場合、Squidは終了前にswap.stateを書き直し、Squidを終了します。

Squidが起動していないときにswap.stateを削除する場合には、どんな情報もキャッシュから失うことはないでしょう。Squidはすべてのキャッシュディレクトリとスワップファイルを調べてキャッシュを再構築します。これはとても長い時間（我慢を）必要とする作業です。

6.13 どのようにすれば安全にログを削除できますか？

Squidが起動している最中は、決して access.log, store.log, cache.log, swap.stat を削除すべきではありません。UNIXではプロセスが実行中でオープンしているファイルでも削除できます。しかし、そのスペースはプログラムが終了してファイルをクローズするまで回収されません。swap.stateは先に説明の通り、削除しても再度構成することができますが、他のファイルは再構成はできません。
Squidの"rotate"機能を使って一日一回はログをローテションすると良いでしょう。　ログは拡張数（*.1,*,2のような）をつけて保存されます。ローテションは、swap.stateをクリーンにします。しかし、拡張数をつけて残すようにはなっていません。

ローテーションを行うコマンドは、

% squid -k rotate

です。たとえば、このコマンドをCRONを使い夜中に実行すると良いでしょう。

0 0 * * * /usr/local/squid/bin/squid -k rotate

6.14 どうすればログを行わないようにできますか？

access.logを無効にするには、設定ファイルで

cache_access_log /dev/null

とします。
store.logを無効にするには、

cache_store_log none

とします。
多くの重要な情報とデバックの際の情報となるため、cache.logを無効にするのは薦められません。　しかしどうしてもしたければ、

cache_log /dev/null

で無効にできます。

6.15 ログファイルがとても大きくなります。

cronの機能を使って、ログをローテションすれば良いでしょう。
例：

0 0 * * * /usr/local/squid/bin/squid -k rotate

6.17 ログファイルの管理

分析の有効なファイルは、access.logです。評価を長期間行うためには、適宜、ログをローテーションしていくと良いでしょう。　Squidには、ローテションのためのAPIが組み込まれており、実行中であっても混乱させることなくログをローテーションできます。

ログファイルの為のディスクスペースを確保して、cronによって例えば、24や12や8時間ごとにローテーションして行くことが望ましいです。

ログファイルは、余裕のある時間帯に圧縮することもできます。log_icp_queriesなどを有効にしていると一日で役1GBのログを生成してしまうかも知れません。

ログの管理にあたり、EUのDESIREプロジェクトでは、ログの管理についての基本ルールを策定しました。

1. 公表にあたってはクライアントのプライバシーを保つ。
2. 解析が終わっても、ログは長い時間保存してください。　殆どの国ではプライバシーに関する法律によって多くの時間、記録を保存していくことが求められます。
3. 少なくとも一日一回はログをローテーションすべきです。そのままにしておくとそれは大きなファイルになってしまいます。
4. 容量を意識しておいてください。　ログの生成よりもログの処理のほうが余計に時間はかかります。

6.18 ERR_NO_CLIENTS_BIG_OBJ というメッセージがでます。

これは要求されたオブジェクトが"あとで削除する"といモードで転送中に、ユーザがアボートしたことを意味します。このようなモードででの転送は、

• maximum_object_sizeよりも大きなオブジェクトであった。
• プロキシのみの機能をもっと隣接サーバからの要求であった。

6.19 ERR_LIFETIME_EXP は何を意味しますか？

クライアントからの要求を転送中にタイムアウトが発生したことを意味しています。多くは検索に時間がかかったためにクライアントが要求をアボートした為でしょう。

Copyright© 1998-2003 ROBATA.ORG