> Squid中文手册 > 第13章 日志文件


第13章 日志文件



13.1 cache.log

cache.log包含多种消息,例如Squid的配置信息、性能警告、以及严重错误。如下是cache.log的输出样本:

2003/09/29 12:09:45| Starting Squid Cache version 2.5.STABLE4 for i386-
    
unknown-freebsd4.8...
    
2003/09/29 12:09:45| Process ID 18990
    
2003/09/29 12:09:45| With 1064 file descriptors available
    
2003/09/29 12:09:45| Performing DNS Tests...
    
2003/09/29 12:09:45| Successful DNS name lookup tests...
    
2003/09/29 12:09:45| DNS Socket created at 0.0.0.0, port 1154, FD 5
    
2003/09/29 12:09:45| Adding nameserver 24.221.192.5 from /etc/resolv.conf
    
2003/09/29 12:09:45| Adding nameserver 24.221.208.5 from /etc/resolv.conf
    
2003/09/29 12:09:45| helperOpenServers: Starting 5 'redirector.pl' processes
    
2003/09/29 12:09:45| Unlinkd pipe opened on FD 15
    
2003/09/29 12:09:45| Swap maxSize 10240 KB, estimated 787 objects
    
2003/09/29 12:09:45| Target number of buckets: 39
    
2003/09/29 12:09:45| Using 8192 Store buckets
    
2003/09/29 12:09:45| Max Mem  size: 8192 KB
    
2003/09/29 12:09:45| Max Swap size: 10240 KB
    
2003/09/29 12:09:45| Rebuilding storage in /usr/local/squid/var/cache (CLEAN)
    
2003/09/29 12:09:45| Using Least Load store dir selection
    
2003/09/29 12:09:45| Set Current Directory to /usr/local/squid/var/cache
    
2003/09/29 12:09:45| Loaded Icons.
    
2003/09/29 12:09:45| Accepting HTTP connections at 0.0.0.0, port 3128, FD 16.
    
2003/09/29 12:09:45| Accepting ICP messages at 0.0.0.0, port 3130, FD 17.
    
2003/09/29 12:09:45| WCCP Disabled.
    
2003/09/29 12:09:45| Ready to serve requests.

每个cache.log条目以时间戳开始,指示消息何时产生。本示例里的日志报告了squid的版本(2.5.STABLE4),以及squid所运行的操作系统标识符(i386-unknown-freebsd4.8)。接下来是进程ID(18990)。许多cache.log条目看起来含义不明(例如Target number of buckets: 39)。大多数正常情形下,可以忽略这些不易理解的条目。另一方面,你也许该仔细看一下本质的配置细节,例如名字服务器的地址,或HTTP服务器地址。本示例日志最后陈述了Squid准备接受请求。此时Squid可以接受来自客户端的HTTP连接。

通常,cache.log增长缓慢。然而,不正常的HTTP事务或类似的事件可以导致squid发布一个debug消息。假如这样的事件经常发生(例如DOS攻击、新的病毒、磁盘意外等),日志文件会增长很快。定期轮转日志减少了用光磁盘的风险。

主要的错误和异常条件最可能报告在cache.log里。我推荐存档这些日志,以便以后回查事件的源头。当在Squid的邮件列表或类似论坛描述这些故障时,相应的cache.log非常有用。某些情形下,你也许应该调大日志的debug级别,以便其他人能更好的理解和修正你的问题。


13.1.1 debug级别

debug_options指令控制cache.log的日志级别。默认值(ALL,1)通常是最佳选择。在更高级别上,不重要的消息会混淆视线。请参考16.2节关于debug_options指令的完整描述。

请注意最高级别的debug(9或10)会对每个请求产生数千行日志,快速消耗磁盘空间和显著影响squid的性能。

可以使用squid的-X命令行选项来对所有情形激活完整的debug。假如squid拒绝启动,并且squid.conf里的debug级别不足以诊断问题时,该模式特别有用。这也是在配置文件解析器解析到debug_options指令之前,激活它的完整debug的好方法。在squid运行正常时,请勿使用-X。

对运行的squid进程,可使用squid的-k debug命令行选项来立刻激活完整debug。这个命令是循环使用的:第一次调用打开完整debug,第二次调用则关闭它。请见第5章关于-k选项的通用讨论。

如前所述,完整debug会产生难以控制的日志增长。这会使squid和操作系统运行缓慢。在极端情形下,你会发现终端session在运行第一个squid -k debug命令后,变得没有响应。在squid狂写日志的同时让操作无法进行,这情形并不好。如下技巧也许有用,它获取5秒钟的debug数据快照:

% squid -k debug; sleep 5; squid -k debug

13.1.2 转发cache.log消息到系统日志

为了让squid发送cache.log消息的拷贝到系统日志,请使用-s命令行选项。仅仅在debug级别0和1的消息会被转发。级别0的消息以syslog级别LOG_WARNING记录,级别1的消息以syslog级别LOG_NOTICE记录。所有消息使用LOCAL4的syslog设备。如下是配置syslogd的一个方法,以便这些消息能保存下来:

local4.warning                           /var/log/squid.log

在维护多个squid主机时,使用syslog来记录cache.log特别方便。可以配置每个本地syslog进程,转发这些消息到中央日志主机,这样就可在一个地方统一浏览所有cache日志。例如,可在/etc/syslogd.conf里使用如下接口:

local4.notice                            @192.168.45.1

13.1.3 dump cache.log消息到终端

-d level命令行选项指示squid去dump cache.log消息到终端(例如stderr)。level参数指明dump出的消息的最大级别。注意你只会见到出现在cache.log里的消息,它遵循于debug_options设置。例如,假如设置了debug_options ALL,1,然后运行squid -d2,你不会见到级别2的debug消息。

-d level和-N选项在debug squid问题或快速测试配置文件的改变时,特别有用。它们允许你容易启动squid和观察cache.log消息。在squid从crontab或类似的设备启动时,该选项也有用,crontab会捕获squid的标准错误并将其报告回用户。例如,可能有如下crontab,它自动重配运行中的squid进程:

15 */4 * * * /usr/local/squid/sbin/squid -d1 -k reconfigure


13.2 access.log

Squid把关于HTTP事务的关键信息存放在access.log里。该文件是基于行的,也就是说每行对应一个客户端请求。squid记录客户端IP(或主机名)、请求URL、响应size、和其他信息。

Squid在access.log里记录所有HTTP访问,除了那些在还没有发送数据前就断开的连接。Squid也记录所有的ICP(非HTCP)事务,除非你使用log_icp_queries指令关闭了这个功能。第13.2.4节描述了其他影响access日志的squid.conf指令。

默认的access.log格式包含了10个域。如下是日志样本,长行分割并且缩进排版:

1066037222.011  126389 9.121.105.207 TCP_MISS/503 1055

        GET http://home.gigigaga.com/n8342133/Miho.DAT.019 -

        DIRECT/203.187.1.180 -

1066037222.011   19120 12.83.179.11 TCP_MISS/200 359

        GET http://ads.x10.com/720x300/Z2FtZ3JlZXRpbmcxLmRhd/7/AMG -

        DIRECT/63.211.210.20 text/html

1066037222.011   34173 166.181.33.71 TCP_MISS/200 559

        GET http://coursesites.blackboard.com:8081/service/collab/./1010706448190/ -

        DIRECT/216.200.107.101 application/octet-stream

1066037222.011   19287 41.51.105.27 TCP_REFRESH_MISS/200 500

        GET http://fn.yam.com/include/tsemark/show.js -

        DIRECT/210.59.224.59 application/x-javascript

1066037222.011   19395 41.51.105.27 TCP_MISS/304 274

        GET http://fnasp.yam.com/image/coin3.gif -

        DIRECT/211.72.254.133 -

1066037222.011   19074 30.208.85.76 TCP_CLIENT_REFRESH_MISS/304 197

        GET http://ads.icq.com/content/B0/0/..bC6GygEYNeHGjBUin5Azfe68m5hD1jLk$/aol -

        DIRECT/64.12.184.121 -

1066037222.011   19048 12.83.179.11 TCP_MISS/200 261

        GET http://ads.adsag.com/js.ng/...ne&cat=friendship&subcat=girltalk -

        DIRECT/209.225.54.119 application/x-javascript

1066037222.118     106 41.51.105.27 TCP_HIT/200 536

        GET http://rcm-images.amazon.com/./images/G/01/rcm/privacy.gif -

        NONE/- image/gif

1066037222.352   19475 27.34.49.248 TCP_MISS/200 12387

        GET http://espanol.geocities.com/lebastias/divulgacion/budismo-tarot.html -

        DIRECT/209.1.225.139 text/html

1066037222.352     132 144.157.100.17 TCP_MISS/504 1293

        GET http://ar.atwola.com/image/93101912/aol -

        NONE/- -

如下是对每个域的详细解释:


1.时间戳



请求完成时间,以Unix纪元(UTC 1970-01-01 00:00:00)以来的秒数表示,它是毫秒级的。squid使用这种格式而不是人工可读的时间格式,是为了简化某些日志处理程序的工作。

可以使用一个简单的perl命令来转化Unix时间戳到本地时间,例如:

perl -pe 's/^\d+\.\d+/localtime($&)/e;' access.log


2.响应时间


对HTTP事务来说,该域表明squid花了多少时间来处理请求。在squid接受到HTTP请求时开始计时,在响应完全送出后计时终止。响应时间是毫秒级的。

对ICP查询来说,响应时间通常是0。这是因为squid回答ICP查询非常迅速。甚至,squid在接受到ICP查询和发送完响应之间,不会更新进程时钟。

尽管时间值是毫秒级的,但是精度可能是10毫秒。在squid负载繁重时,计时变得没那么精确。



3.客户端地址


该域包含客户端的IP地址,或者是主机名--假如激活了log_fqdn。出于安全或隐私的理由,你可能需要使用client_netmask指令来掩盖客户端地址的一部分。然而,这样让来自同一客户端的组请求变得不可能。



4.结果/状态码


该域包含2个token,以斜杠分隔。第一个token叫结果码,它把协议和事务结果(例如TCP_HIT或UDP_DENIED)进行归类。这些是squid专有的编码,在13.2.1节里有定义。以TCP_开头的编码指HTTP请求,以UDP_开头的编码指ICP查询。

第2个token是HTTP响应状态码(例如200,304,404等)。状态码通常来自原始服务器。在某些情形下,squid可能有义务自己选择状态码。这些编码在HTTP的RFC里定义,在随后的Table 13-1里有概述。



5.传输size


该域指明传给客户端的字节数。严格的讲,它是squid告诉TCP/IP协议栈去发送给客户端的字节数。这就是说,它不包括TCP/IP头部的overhead。也请注意,传输size正常来说大于响应的Content-Length。传输size包括了HTTP响应头部,然而Content-Length不包括。

传输size可用于近似的带宽使用分析,但并非精确的HTTP实体size计算。假如需要了解响应的Content-Length,可在store.log里找到它。



6.请求方式


该域包含请求方式。因为squid客户端可能使用ICP或HTTP,请求方式就可能是HTTP-或ICP-这2种。最普通的HTTP请求方式是GET。ICP查询总以ICP_QUERY的形式被记载。请见6.1.2.8节关于squid了解的HTTP方式列表。



7.URI


该域包含来自客户端请求的URI。大多数记录下来的URI实际是URL(例如,它们有主机名)。

Squid对某些失败使用特殊的记录格式。例如Squid不能解析HTTP请求,或者不能决定URI,这时你可能见到类似于"error:invalid-request." 的字串出现在URI的位置。例如:

1066036250.603 310 192.0.34.70 NONE/400 1203 GET error:invalid-request - NONE/- -

另外在该域里,也请留心URI里的空格字符。取决于uri_whitespace设置,squid可能在日志文件里打印URI时带空格字符。若发生这种情况,则阅读access.log文件的日志分析工具可能会遇到麻烦。

在记日志时,squid删掉了在第一个问号(?)之后的所有URI字符,除非禁用了strip_query_terms指令。



8.客户端身份


Squid有2种不同的办法来决定用户的身份。一种是RFC 1413身份协议,另一种来自HTTP验证头部。

Squid试图基于ident_lookup_access规则进行身份查询,假如有的话。另外,假如使用代理验证(或在代理人模式下的规范服务验证),squid会在该域放置给定的用户名。假如2者都提供给squid一个用户名,并且你使用了原始access.log格式,那么HTTP验证名字会记录下来,RFC 1413名字会忽略掉。普通日志文件格式会把两者都独立的记录。



9.对端编码/对端主机


对端信息包含了2个token,以斜杠分隔。它仅仅与cache丢失的请求有关。第一个token指示如何选择下一跳,第二个token是下一跳的地址。对端编码列在13.2.3节里。

当squid发送一个请求到邻居cache时,对端主机地址是邻居的主机名。假如请求是直接送到原始服务器的,则squid会写成原始服务器的IP地址或主机名--假如禁用了log_ip_on_direct。NONE/-这个值指明squid不转发该请求到任何其他服务器。



10.内容类型

原始access.log的默认的最后一个域,是HTTP响应的内容类型。squid从响应的Content-Type头部获取内容类型值。假如该头部丢失了,squid使用一个横杠(-)代替。

假如激活了log_mime_headers指令,squid在每行追加2个附加的域:



11.HTTP请求头部


Squid编码HTTP请求头部,并且在一对方括号之间打印它们。方括号是必须的,因为squid不编码空格字符。编码方案稍许奇怪。回车(ASCII 13)和换行(ASCII 10)分别打印成\r和\n。其他不可打印的字符以RFC 1738风格来编码,例如Tab(ASCII 9)变成了%09。



12.HTTP响应头部


Squid编码HTTP响应头部,并且在一对方括号之间打印它们。注意这些是发往客户端的头部,可能不同于从原始服务器接受到的头部。

Squid只有在整个响应发送到客户端完成以后,才写access.log日志。这点允许squid在日志文件里包含请求和响应两者信息。然而,需要花费数分钟甚至数小时才能完成的事务,请求期间的日志在access.log里不可见。当这类型的事务呈现出性能或策略问题时,access.log可能对你没有帮助。代替的,可使用cache管理器来浏览挂起事务的列表(见14章)。


13.2.1 access.log结果编码

相应于HTTP请求,下列标签可能出现在access.log文件的第四个域。

TCP_HIT

Squid发现请求资源的貌似新鲜的拷贝,并将其立即发送到客户端。

TCP_MISS

Squid没有请求资源的cache拷贝。

TCP_REFERSH_HIT

Squid发现请求资源的貌似陈旧的拷贝,并发送确认请求到原始服务器。原始服务器返回304(未修改)响应,指示squid的拷贝仍旧是新鲜的。

TCP_REF_FAIL_HIT

Squid发现请求资源的貌似陈旧的拷贝,并发送确认请求到原始服务器。然而,原始服务器响应失败,或者返回的响应Squid不能理解。在此情形下,squid发送现有cache拷贝(很可能是陈旧的)到客户端。

TCP_REFRESH_MISS

Squid发现请求资源的貌似陈旧的拷贝,并发送确认请求到原始服务器。原始服务器响应新的内容,指示这个cache拷贝确实是陈旧的。

TCP_CLIENT_REFRESH_MISS

Squid发现了请求资源的拷贝,但客户端的请求包含了Cache-Control: no-cache指令。Squid转发客户端的请求到原始服务器,强迫cache确认。

TCP_IMS_HIT

客户端发送确认请求,Squid发现更近来的、貌似新鲜的请求资源的拷贝。Squid发送更新的内容到客户端,而不联系原始服务器。

TCP_SWAPFAIL_MISS

Squid发现请求资源的有效拷贝,但从磁盘装载它失败。这时squid发送请求到原始服务器,就如同这是个cache丢失一样。

TCP_NEGATIVE_HIT

在对原始服务器的请求导致HTTP错误时,Squid也会cache这个响应。在短时间内对这些资源的重复请求,导致了否命中。negative_ttl指令控制这些错误被cache的时间数量。请注意这些错误只在内存cache,不会写往磁盘。下列HTTP状态码可能导致否定cache(也遵循于其他约束): 204, 305, 400, 403, 404, 405, 414, 500, 501, 502, 503, 504。

TCP_MEM_HIT

Squid在内存cache里发现请求资源的有效拷贝,并将其立即发送到客户端。注意这点并非精确的呈现了所有从内存服务的响应。例如,某些cache在内存里,但要求确认的响应,会以TCP_REFRESH_HIT, TCP_REFRESH_MISS等形式记录。

TCP_DENIED

因为http_access或http_reply_access规则,客户端的请求被拒绝了。注意被http_access拒绝的请求在第9域的值是NONE/-,然而被http_reply_access拒绝的请求,在相应地方有一个有效值。

TCP_OFFLINE_HIT

当offline_mode激活时,Squid对任何cache响应返回cache命中,而不用考虑它的新鲜程度。

TCP_REDIRECT

重定向程序告诉Squid产生一个HTTP重定向到新的URI(见11.1节)。正常的,Squid不会记录这些重定向。假如要这样做,必须在编译squid前,手工定义LOG_TCP_REDIRECTS预处理指令。

NONE

无分类的结果用于特定错误,例如无效主机名。

相应于ICP查询,下列标签可能出现在access.log文件的第四域。

UDP_HIT

Squid在cache里发现请求资源的貌似新鲜的拷贝。

UDP_MISS

Squid没有在cache里发现请求资源的貌似新鲜的拷贝。假如同一目标通过HTTP请求,就可能是个cache丢失。请对比UDP_MISS_NOFETCH。

UDP_MISS_NOFETCH

跟UDP_MISS类似,不同的是这里也指示了Squid不愿去处理相应的HTTP请求。假如使用了-Y命令行选项,Squid在启动并编译其内存索引时,会返回这个标签而不是UDP_MISS。

UDP_DENIED

因为icp_access规则,ICP查询被拒绝。假如超过95%的到某客户端的ICP响应是UDP_DENIED,并且客户端数据库激活了(见附录A),Squid在1小时内,停止发送任何ICP响应到该客户端。若这点发生,你也可在cache.log里见到一个警告。

UDP_INVALID

Squid接受到无效查询(例如截断的消息、无效协议版本、URI里的空格等)。Squid发送UDP_INVALID响应到客户端。


13.2.2 HTTP响应状态码

Table 13-1列出了数字HTTP响应CODE和理由短句。注意Squid和其他HTTP客户端仅仅关注这些数字值。理由短句是纯解释性的,不会影响响应的意义。对每个状态码,也提供了一个到RFC 2616的具体节的索引。注意状态码0和600是squid使用的非标准的值,不会在RFC里提到。


Table 13-1. HTTP response status codes
Code Reason phrase RFC 2616 section
0 No Response Received (Squid-specific) N/A
1xx Informational 10.1
100 Continue 10.1.1
101 Switching Protocols 10.1.2
2xx Successful 10.2
200 OK 10.2.1
201 Created 10.2.2
202 Accepted 10.2.3
203 Non-Authoritative Information 10.2.4
204 No Content 10.2.5
205 Reset Content 10.2.6
206 Partial Content 10.2.7
3xx Redirection 10.3
300 Multiple Choices 10.3.1
301 Moved Permanently 10.3.2
302 Found 10.3.3
303 See Other 10.3.4
304 Not Modified 10.3.5
305 Use Proxy 10.3.6
306 (Unused) 10.3.7
307 Temporary Redirect 10.3.8
4xx Client Error 10.4
400 Bad Request 10.4.1
401 Unauthorized 10.4.2
402 Payment Required 10.4.3
403 Forbidden 10.4.4
404 Not Found 10.4.5
405 Method Not Allowed 10.4.6
406 Not Acceptable 10.4.7
407 Proxy Authentication Required 10.4.8
408 Request Timeout 10.4.9
409 Conflict 10.4.10
410 Gone 10.4.11
411 Length Required 10.4.12
412 Precondition Failed 10.4.13
413 Request Entity Too Large 10.4.14
414 Request-URI Too Long 10.4.15
415 Unsupported Media Type 10.4.16
416 Requested Range Not Satisfiable 10.4.17
417 Expectation Failed 10.4.18
5xx Server Error 10.5
500 Internal Server Error 10.5.1
501 Not Implemented 10.5.2
502 Bad Gateway 10.5.3
503 Service Unavailable 10.5.4
504 Gateway Timeout 10.5.5
505 HTTP Version Not Supported 10.5.6
6xx Proxy Error N/A
600 Unparseable Response Headers (Squid-specific) N/A

假如Squid从原始服务器没有接受到任何响应,你可在access.log里看到状态码0。假如Squid接受到的响应没有包含HTTP头部,就会出现状态码600。在少数情况下,某些原始服务器仅发送响应body,而忽略了任何头部。


13.2.3 access.log对端编码

下列编码可能出现在access.log的第9域。请参考10.10节关于Squid如何对cache丢失情况,选择有效的下一跳。

NONE

这指明Squid对本次请求,不会与任何其他服务器(邻居或原始服务器)通信。它通常与cache命中、拒绝请求、cache管理请求、错误、和所有的ICP查询这些类型联合出现。

DIRECT

Squid直接转发请求到原始服务器。该域的第2半部分显示原始服务器的IP地址,或主机名--假如禁止了log_ip_on_direct。

SIBLING_HIT

在姐妹cache返回ICP或HTCP命中后,Squid发送请求到姐妹cache。

PARENT_HIT

在父cache返回ICP或HTCP命中后,Squid发送请求到父cache。

DEFAULT_PARENT

Squid选择该父cache,因为其在squid.conf的cache_peer行里被标志为default。

FIRST_UP_PARENT

Squid转发请求到该父cache,因为它是位于已知活跃列表里的第一个父cache。

FIRST_PARENT_MISS

Squid转发请求到该父cache,它第一个响应ICP/HTCP丢失消息。换句话说,对这个特殊的ICP/HTCP查询,在这个特殊时刻,被选中的父cache有最佳的往返时间(RTT)。注意标准RTT可能被人工矫正过,取决于cache_peer指令的weight选项。

CLOSEST_PARENT_MISS

Squid选择该父cache,因为它报告到原始服务器的RTT最低。这点仅在2个cache都激活了netdb,并且原始服务器(或在同一子网内的其他server)返回ICMP ping消息。

CLOSEST_PARENT

这点类似CLOSEST_PARENT_MISS,除了RTT计算不是来自ICP/HTCP响应消息外。代替的,它们来自Squid保留的更老的计算方式,例如netdb交换功能。

CLOSEST_DIRECT

Squid基于netdb算法,转发请求到原始服务器。这点在满足下述任何条件时发生:

  • 1)在Squid和原始服务器之间的RTT小于配置的minimum_direct_rtt值。

  • 2)在Squid和原始服务器之间的标准路由跳数少于配置的minimum_direct_hops值。

  • 3)在ICP/HTCP响应里返回的RTT值,指示Squid离原始服务器近于任何其他邻居。

ROUNDROBIN_PARENT

Squid转发请求到该父cache,因为设置了round-robin选项,并且它有最低的使用计数器。

CD_PARENT_HIT

Squid基于cache摘要算法(见10.7节)转发请求到该父cache。

CD_SIBLING_HIT

Squid基于cache摘要算法转发请求到该姐妹cache。

CARP

Squid选择该父cache,基于cache数组路由协议算法(见10.9节)。

ANY_PARENT

作为最后的手段,Squid选择该父cache,因为没有其他方法能选择可行的下一跳。

注意大部分上述编码可能以TIMEOUT_开头,这表明在等待ICP/HTCP响应时发生超时。例如:

1066038165.382    345 193.233.46.21 TCP_MISS/200 2836

        GET http://www.caida.org/home/./images/home.jpg

        TIMEOUT_CLOSEST_DIRECT/213.219.122.19 image/jpeg

可使用icp_query_timeout指令来调整超时。


13.2.4 影响access.log的配置指令

下列配置文件指令会影响到access.log。

13.2.4.1 log_icp_queries

该指令默认激活,导致squid记录所有的ICP查询。假如运行了一个繁忙的父cache,这点可能让access.log文件变得巨大。为了节省磁盘空间,可禁止该指令:

log_icp_queries off

假如禁止了ICP查询的日志,我建议你监视查询数量--通过cache管理器或SNMP。

13.2.4.2 emulate_httpd_log

access.log文件有2种格式:普通格式和原始格式。普通格式就如同大部分HTTP服务器(如Apache)的日志格式一样。它包含的信息少于Squid的原始格式。然而,假如运行Squid在代理人模式下(见15章),你可能想要普通日志文件格式。普通格式或许也对你现有的日志文件分析工具有用。使用该指令来激活普通格式:

emulate_httpd_log on

请见http://www.w3.org/Daemon/User/Config/Logging.html#common-logfile-format 关于该格式的描述。

13.2.4.3 log_mime_hdrs

使用log_mime_hdrs让squid记录HTTP请求和响应的头部:

log_mime_headers on

在激活时,squid追加请求和响应头部到access.log。这会在每行增加2个域。每个域都以方括号引用起来,便于分析。某些字符会被编码来保证日志文件可读。Table 13-2显示了这些编码方案。


Table 13-2. Character encoding rules for HTTP headers in access.log

Character Encoding
Newline \n
Carriage return \r
Backslash \\
[ %5b
] %5d
% %25
ASCII 0-31 %xx (hexadecimal value)
ASCII 127-255 %xx (hexadecimal value)
13.2.4.4 log_fqdn

Squid默认把客户端IP地址放在access.log里。也可以记录可用的主机名,激活如下指令:

log_fqdn on

这点让Squid在接受到请求时,对客户端的地址发起反向DNS查询。假如在请求完成时查到了主机名,Squid就将它放在第3域。

13.2.4.5 ident_lookup_access

该访问规则列表决定Squid是否对客户端的TCP连接发起RFC 1413身份查询。默认情况下,Squid不会发布身份查询。为了激活这点,简单的增加一个或多个规则:

acl All src 0/0

ident_lookup_access allow All

假如在请求完成时查到了答案,Squid将其放在第8域。假如同时使用了HTTP验证,从验证得到的用户名会取代身份查询答案。

13.2.4.6 log_ip_on_direct

当Squid转发cache丢失到原始服务器时,它在第9域记录原始服务器的IP地址。可以禁止这个指令,以便squid记录主机名:

log_ip_on_direct off

在此情形下,主机名来自于URI。假如URI包含了IP地址,Squid不会将其转换为主机名。

13.2.4.7 client_netmask

该指令存在主要是为了保护用户的隐私。不同于记录完整的IP地址,你也可以掩盖一些位。例如:

client_netmask 255.255.255.0

在此设置下,access.log里的所有客户端IP地址的最后一个八位组是0:

1066036246.918     35 163.11.255.0 TCP_IMS_HIT/304 266 GET http://...

1066036246.932     16 163.11.255.0 TCP_IMS_HIT/304 266 GET http://...

1066036247.616    313 140.132.252.0 TCP_MISS/200 1079 GET http://...

1066036248.598  44459 140.132.252.0 TCP_MISS/500 1531 GET http://...

1066036249.230     17 170.210.173.0 TCP_IMS_HIT/304 265 GET http://...

1066036249.752   2135 140.132.252.0 TCP_MISS/200 50230 GET http://...

1066036250.467      4 170.210.173.0 TCP_IMS_HIT/304 265 GET http://...

1066036250.762    102 163.11.255.0 TCP_IMS_HIT/304 265 GET http://...

1066036250.832     20 163.11.255.0 TCP_IMS_HIT/304 266 GET http://...

1066036251.026     74 203.91.150.0 TCP_CLIENT_REFRESH_MISS/304 267 GET http://...
13.2.4.8 strip_query_terms

该指令是另一个隐私保护功能。在记录请求前,Squid删除了查询条件。假如日志文件不幸落入坏人之手,他们不会找到任何用户名和密码。当该指令激活时,在问号(?)之后的所有字节被删除。例如,某个URI如下:

http://auto.search.msn.com/response.asp?MT=www.kimo.com.yw&srch=3&prov=&utf8

会被记录为:

http://auto.search.msn.com/response.asp?
13.2.4.9 uri_whitespace

早前我提到过出现在某些URI里的空格字符的问题。RFC申明URI必须不包括空格字符,但在实际中情况并非如此。uri_whitespace指令指明Squid如何处理这种情况。允许的设置是:strip (default), deny, allow, encode, 和chop。在这些设置里,strip,encode和chop保证URI域不包含任何空格字符(空格字符会给access.log增加多余的域)。

allow设置允许请求不加修改的通过Squid。它很可能会给重定向器和日志文件解析器带来麻烦。与之相反的是deny设置,它导致Squid拒绝这种请求。用户会接受到错误消息,但请求仍带着空格字符被记录到access.log。

假如设置为encode,Squid将空格字符按RFC 1738规范来编码。这点其实用户代理应该先做到。chop设置导致Squid把第一个空格字符后的URI都截断。

默认设置是strip,它让Squid从URI里移除空格字符。这确保日志文件解析器和重定向器工作正常,但可能会破坏某些事情,例如不正确编码的搜索引擎查询。

13.2.4.10 buffered_logs

默认情况下,Squid禁止写cache.log文件的buffer,这允许你运行tail -f 命令实时的观察日志文件变化。假如你认为这点导致不必要的性能开销,就可以禁用buffer:

buffered_logs off

然而,除非以完整debug模式运行Squid,这点可能无关紧要。注意该选项仅仅影响cache.log。其他的日志文件总使用非缓冲的写方式。


13.2.5 access.log分析工具

access.log包含很多信息,远不止你简单的浏览该文件所见。为了完整的浏览,必须使用第三方的日志文件分析包。你可在Squid的web页面的链接里,找到它们的列表。或者直接访问:http://www.squid-cache.org/Scripts/.

最流行的工具之一是Calamaris -- 一个Perl脚本,解析日志文件并产生基于文本的或HTML的报告。它提供关于会话的详细分类包括请求方式、客户端IP地址、原始服务器域名、内容类型、文件名扩展、响应size、以及更多。Calamaris也报告ICP查询会话,甚至其他cache产品的日志分析。其站点是:http://calamaris.cord.de.

Squeezer以及它的派生Squeezer2,是Squid专有的分析工具。它们提供许多统计,能帮助你了解Squid的性能,特别是在有邻居cache时。两者都产生HTML文件作为输出。squid-cache.org站点的Logfile Analysis页有这些程序的链接。

Webalyzer是另一个有用工具。它运行快速,并且产生带表格和柱形统计表的HTML页面。它原始是设计成分析原始服务器的访问日志的。尽管它能解析Squid的日志,但不会报告诸如命中率和响应时间的事件。它使用的某些条款不同于我的做法。例如,Webalyzer把任何请求叫做一个"命中",这不同于cache命中。它也把"页面"和"文件"加以区别。更多信息请访问Webalyzer的主页:http://www.mrunix.net/webalyzer/.



13.3 store.log

store.log记录Squid关于存储或删除cache目标的决定。对每个存在cache里的目标、每个不可cache的目标、以及每个被轮换策略删除的目标,Squid都会创建相应的日志条目。该日志文件内容既包含了内存cache又包含了磁盘cache。

store.log提供了下述不能从access.log获取的内容:

  • 1)某个特定的响应是否被cache。
  • 2)cache目标的文件号。对UFS基础的存储机制,你可转换该文件号到路径名,并且检查cache文件的内容。
  • 3)响应的内容长度:包括Content-Length值和实际的body大小。
  • 4)Date, Last-Modified, 和Expires头部的值。
  • 5)响应的cache关键字(例如MD5哈希值)。

如你所见,这些都是相对低级的信息,在日常管理中可能用不上。除非你要做专业的分析,或打算debug某程序,否则store.log可有可无。可以如下来禁止它:

cache_store_log none

跟其他日志文件一样,Squid将最新的日志条目写到该文件的末尾。某个给定的URI可能出现在日志文件里多次。例如,它先被cache,然后删除,接着又cache住。仅仅最近来的日志条目才反映目标的当前值。

store.log是文本基础的,看起来如下:

1067299212.411 RELEASE -1 FFFFFFFF A5964B32245AC98592D83F9B6EA10B8D 206

    1067299212 1064287906 -1 application/octet-stream 6840/6840

    GET http://download.windowsupdate.com/msdownload/update/v3-19990518/cab...

1067299212.422 SWAPOUT 02 0005FD5F 6F34570785CACABC8DD01ABA5D73B392 200

    1067299210 1057899600 -1 image/gif 1125/1125

    GET http://forum.topsportsnet.com/shf./images/nav_members1.gif

1067299212.641 RELEASE -1 FFFFFFFF B0616CB4B7280F67672A40647DD08474 200

    1067299212 -1 -1 text/html -1/67191

    GET http://www.tlava.com/

1067299212.671 RELEASE -1 FFFFFFFF 5ECD93934257594825659B596D9444BC 200

    1067299023 1034873897 1067299023 image/jpeg 3386/3386

    GET http://ebiz0.ipixmedia.com/abc/ebiz/_EBIZ_3922eabf57d44e2a4c3e7cd234a...

1067299212.786 RELEASE -1 FFFFFFFF B388F7B766B307ADEC044A4099946A21 200

    1067297755 -1 -1 text/html -1/566

    GET http://www.evenflowrocks.com/pages/100303pic15.cfm

1067299212.837 RELEASE -1 FFFFFFFF ABC862C7107F3B7E9FC2D7CA01C8E6A1 304

    1067299212 -1 1067299212 unknown -1/0

    GET http://ebiz0.ipixmedia.com/abc/ebiz/_EBIZ_3922eabf57d44e2a4c3e7cd234a...

1067299212.859 RELEASE -1 FFFFFFFF 5ED2726D4A3AD83CACC8A01CFDD6082B 304

    1066940882 1065063803 -1 application/x-javascript -1/0

    GET http://www.bellsouth.com/scripts/header_footer.js

每个日志条目包含如下13个域:

  • 1. 时间戳

    事件何时发生,表现为Unix纪元以来的秒数,它是毫秒级的。

  • 2. 动作

  • cache目标发生的动作。该域有3个可能值:SWAPOUT,RELEASE,和SO_FAIL。

    • 1)SWAPOUT在Squid成功的存储目标到磁盘时发生。某些目标例如那些消极cache的,仅保存在内存而不是磁盘,Squid不会在store.log里记录它们。

    • 2)SO_FAIL表明Squid不能完整的存储目标到磁盘。多半意味着存储机制拒绝以写方式打开新的磁盘文件。

    • 3)RELEASE在Squid从cache里删除目标,或首先就决定响应不可存储时发生。


  • 3. 目录号

  • 目录号是十进制小数形式,它是个到cache目录的7位索引。对没有存储到磁盘的目标,该域包含-1值。

  • 4. 文件号

  • 文件号是25位的标识符,内在的被squid使用。它被写成8字符的十六进制号。对UFS基础的存储机制,有算法可以转换文件号到路径名(见13.3.1节)。没有存储到磁盘的目标,没有有效的文件号。对这些目标,该域的值是FFFFFFFF。仅仅在RELEASE和SO_FAIL情况下才会出现这个值。

  • 5. cache关键字

    Squid使用MD5哈希值作为主要的索引来定位目标。该关键字基于请求方式、URI、和其他可能的信息计算得来。可以从cache关键字来查找store.log条目。然而请注意,目标的cache关键字可能改变。当Squid在access.log里记录TCP_REFRESH_MISS请求时,这点会发生。情况类似如下:
    1065837334.045 SWAPOUT ... 554BACBD2CB2A0C38FF9BF4B2239A9E5 ... http://blah
    
    1066031047.925 RELEASE ... 92AE17121926106EB12FA8054064CABA ... http://blah
    
    1066031048.074 SWAPOUT ... 554BACBD2CB2A0C38FF9BF4B2239A9E5 ... http://blah
    发生了什么呢?该目标原本cache在某个关键字下(554B...)。一段时间后,Squid接受到对该目标的另一请求,并转发确认请求到原始服务器。当响应以新内容返回时,Squid改变旧目标的cache关键字(92AE...),以便它能授予新目标正确的关键字(554B...)。然后旧目标删除,新目标存储到磁盘。

  • 6. 状态码

  • 该域显示响应的HTTP状态码,跟access.log一样。表13.1是状态码列表。

  • 7. 日期

  • HTTP响应的Date头部值,表现为Unix纪元以来的秒数。值-1表示Date头部不可解析,-2意味着头部完缺。

  • 8. 最后修改时间

  • HTTP响应的Last-Modified头部值,表现为Unix纪元以来的秒数。值-1表示Last-Modified头部不可解析,-2意味着头部完缺。

  • 9. 过期时间

  • HTTP响应的Expires头部值,表现为Unix纪元以来的秒数。值-1表示Expires头部不可解析,-2意味着头部完缺。

  • 10. 内容类型

  • HTTP响应的Content-Type头部值,排除了任何media-type参数。假如Content-Type丢失了,Squid插入值unknown。

  • 11. 内容长度/大小

  • 该域包含2个数字,以斜杠分开。第一个是Content-Length头部值。-1表明Content-Length头部不存在。第二个是HTTP消息body的实际大小。你可使用这2个数字来部分的验证接受到的响应,并验证原始服务器是否不正确的计算了内容长度。大多数情形下,这2个数字相等。

  • 12. 方式

  • 请求目标的HTTP方式,跟access.log里的一样。

  • 13. URI

  • 最后一个域是请求URI,跟access.log里的一样。该域也有前述章节提到的空格问题。然而,这里不必为此担忧,因为你可安全的忽略任何多余的域。

  • 对许多RELEASE的条目,在最后8个域出现的是疑问号(?)。这是因为这些域的大部分值来自squid称为MemObject的结构。该结构仅在目标已被接受时,或目标被完整存储在内存时,才会出现。Squid cache里的大部分目标没有MemObject结构,因为它们仅存在于磁盘。对这些情况,Squid在相应域放置一个疑问号。

13.3.1 转换文件号到路径名

假如想要检查某个特定的cache文件,你可稍费工夫将文件号转换到路径名。另外目录号和L1和L2值也是必需的。在squid的源代码里,storeUfsDirFullPath( )函数做这个事情。可在src/fs/ufs/store_dir_ufs.c文件里找到它。如下短小的perl脚本模拟了当前算法:

#!/usr/bin/perl

$L1 = 16;

$L2 = 256;

while (<>) {

    $filn = hex($_);

    printf("%02X/%02X/%08X\n",

        (($filn / $L2) / $L2) % $L1,

        ($filn / $L2) % $L2,

        $filn);

}

这样使用它:

% echo 000DCD06 | ./fileno-to-pathname.pl

0D/CD/000DCD06

要在第N个cache_dir里找到该文件,简单的进入到相应的目录,并列出或查看该文件:

% cd /cache2

% ls -l 0D/CD/000DCD06

-rw-------  1 squid  squid  391 Jun  3 12:40 0D/CD/000DCD06

    % less 0D/CD/000DCD06


13.4 referer.log

可选的referer.log包含了来自客户端请求的Referer头部。为了使用该功能,必须在./configure时打开--enable-referer-log选项。还必须用referer_log指令来指定一个路径。例如:

referer_log /usr/local/squid/var/logs/referer.log

假如想禁止referer.log,则可设置文件名为none。

Referer头部正常情况下包含一个URI,从这个URI获取到了请求(见RFC2616的14.36节)。例如,当web浏览器发布请求到某个内嵌图片时,Referer头部被设置成包含该图片的HTML网页的URI。当你点击HTML超链接时,它也被设置。某些web站点管理员使用Referer值来查找死链接。在使用Squid作为代理人模式时,你也许发现referer.log特别有用。

referer.log格式简单,仅有4个域。如下是一些示例:

1068047502.377 3.0.168.206

    http://www.amazon.com/exec/obidos/search-handle-form/002-7230223-8205634

    http://www.amazon.com/exec/obidos/ASIN/0596001622/qid=1068047396/sr=2-1/...

1068047503.109 3.0.168.206

    http://www.amazon.com/exec/obidos/ASIN/0596001622/qid=1068047396/sr=2-1/...

    http://g-images.amazon.com/./images/G/01/gourmet/gourmet-segway.gif

1068047503.196 3.0.168.206

    http://www.amazon.com/exec/obidos/ASIN/0596001622/qid=1068047396/sr=2-1/...

    http://g-images.amazon.com/./images/G/01/marketing/cross-shop/arnold/appar...

1068047503.198 3.0.168.206

    http://www.amazon.com/exec/obidos/ASIN/0596001622/qid=1068047396/sr=2-1/...

    http://g-images.amazon.com/./images/G/01/marketing/cross-shop/arnold/appar...

1068047503.825 3.0.168.206

    http://www.amazon.com/exec/obidos/ASIN/0596001622/qid=1068047396/sr=2-1/...

    http://images.amazon.com/./images/P/B00005R8BC.01.TZZZZZZZ.jpg

1068047503.842 3.0.168.206

    http://www.amazon.com/exec/obidos/ASIN/0596001622/qid=1068047396/sr=2-1/...

    http://images.amazon.com/./images/P/0596001622.01._PE_PI_SCMZZZZZZZ_.jpg

注意缺少Referer头部的请求不会被记录。这4个域描述如下:

  • 1. 时间戳

  • 请求时间,表现为Unix纪元以来的秒数,是毫秒级的。

注意的是,不像access.log,referer.log在Squid接受到完整请求时,会立刻记录。这样,referer.log条目在access.log之前发生,后者等待响应完成才记录。

  • 2. 客户端地址

  • 客户端地址跟access.log里的一样。log_fqdn和client_netmask指令也影响该日志文件。

  • 3. referer

  • 来自客户端请求的Referer头部值。注意referer值可能有空格字符或其他字符,在写referer.log前Squid不会对其进行编码。

  • 4. URI

  • 客户端正请求的URI。它匹配access.log里的URI。


13.5 useragent.log

可选的useragent.log包含来自客户端请求的User-Agent头部值。为了使用该功能,必须在运行./configure时打开--enable-useragent-log选项。还必须使用useragent_log指令来提供一个路径名。例如:

useragent_log /usr/local/squid/var/logs/useragent.log

User-Agent头部正常情况下包含了发起请求的user-agent的描述。大多数情形下,该描述只是简单的产品名列表和版本信息。你应该清楚应用程序可以轻易的提供伪造的user-agent信息。现代user-agent提供途径可定制该描述。甚至Squid在转发请求里能改变这个User-Agent头部。

useragent.log格式相对简单,看起来如下:

3.0.168.206 [05/Nov/2003:08:51:43 -0700]

    "Mozilla/5.0 (compatible; Konqueror/3; FreeBSD)"

3.0.168.207 [05/Nov/2003:08:52:18 -0700]

    "Opera/7.21 (X11; FreeBSD i386; U)  [en]"

4.241.144.204 [05/Nov/2003:08:55:11 -0700]

    "Mozilla/5.0 (Macintosh; U; PPC Mac OS X; en-us) AppleWebKit/103u (KHTM..."

3.0.168.206 [05/Nov/2003:08:51:43 -0700]

    "Java1.3.1_01"

64.68.82.28 [05/Nov/2003:08:52:50 -0700]

    "Googlebot/2.1 (http://www.googlebot.com/bot.html)"

3.0.168.205 [05/Nov/2003:08:52:50 -0700]

    "WebZIP/4.1 (http://www.spidersoft.com)"

4.241.144.201 [05/Nov/2003:08:52:50 -0700]

    "Mozilla/4.0 (compatible; MSIE 5.0; Windows 98; DigExt; Hotbar 3.0)"

3.0.168.206 [05/Nov/2003:08:54:40 -0700]

    "Bookmark Renewal Check Agent [http://www.bookmark.ne.jp/] (Version 2.0..."

不像其他日志文件,它仅有3个域:

  • 1. 客户端地址

  • 跟access.log里的一样。log_fqdn和client_netmask指令也影响该日志文件。

  • 2. 时间戳

  • 不像其他日志文件那样,用Unix纪元以来的秒数来描述时间,这里使用人工可读的格式。它是HTTP通用日志文件格式的时间戳,看起来如下:
    [10/Jun/2003:22:38:36 -0600]
    注意方括号界定时间戳,它包含一个空格。也请注意,跟referer.log一样,这些条目在Squid接受到完整请求时,立刻被记录。

  • 3. user-agent

  • User-Agent头部的值。这些字串几乎总包含空格。在将其写入日志文件时,Squid不会编码User-Agent值。


13.6 swap.state

swap.state文件是目标写入cache目录、或从cache目录删除的日志写照。每个cache_dir有它自己的swap.state文件。当Squid启动时,它读取swap.state文件来重建cache目标的内存索引。这些文件对Squid管理来说,至关重要。

默认情况下,每个cache.state文件位于它相应的cache目录。这样,每个state文件自动驻留在每个cache_dir下。这点很有用--假如你想重新排序cache_dir行,或想从cache_dir列表里删除条目的话。

如果想将它们放在其他位置,可使用cache_swap_log指令来做:

cache_swap_log /usr/local/squid/var/logs/swap.state

在此情况下,Squid对每个cache目录创建一个swap.state文件,并增加数字后缀。例如,假如有4个cache目录,Squid创建如下日志:

/usr/local/squid/var/logs/swap.state.00

/usr/local/squid/var/logs/swap.state.01

/usr/local/squid/var/logs/swap.state.02

/usr/local/squid/var/logs/swap.state.03

在这个情形下,如果你要增加、删除、或重排序cache_dir行,就必须手工重命名swap.state文件,以保持事情一致。

技术上,swap.state格式是独立于存储机制的。然而,在当前版本的Squid里,所有的存储机制使用同一种格式。swap.state文件使用修正大小(48位)的二进制格式。各个域值以主机字节顺序记录,这样在不同的操作系统之间不便迁移。表13-3描述了swap.state日志条目的各个域的说明。


Table 13-3. swap.state entry fields

Name Size, in bytes Description
op 1 Operation on the entry: added (1) or deleted (2).
file number 4 Same as the fourth field of store.log, except it is stored in binary.
timestamp 4 A timestamp corresponding to the time when the response was generated or last validated. Taken from the Date header for responses that have one. Stored as the number of seconds since the Unix epoch.
lastref 4 A timestamp corresponding to the most recent access to the object.
expires 4 The object's expiration time, taken from an Expires header or Cache-Control max-age directive.
last-modified 4 The object's Last-Modified value.
swap file size 4 The amount of space the object occupies on disk. This includes HTTP headers and other Squid-specific meta-information.
refcount 2 The number of times this object has been requested.
flags 2 Various internal flags used by Squid.
key 16 The MD5 hash of the corresponding URI. Same as the key in store.log, except this one is stored in binary.


13.7 轮转日志

Squid不断的写日志,假如cache非常忙,那么在一段时间后,这些日志文件可能变得很大。某些操作系统甚至限制了文件的最大size(例如2G),假如写文件超过了这个size就会报错。为了保持日志文件容易管理,以及让Squid正常工作,必须定期轮转日志。

Squid有内建的功能用于轮转日志。可通过squid -k rotate命令来调用它,然后告诉Squid对每个日志文件保持多少份旧拷贝。例如,假如设置它为7,对每个日志文件会有8个版本:1个当前的,和7个旧的。

旧日志文件以数字扩展来重命名。例如,当执行一次轮转时,Squid重命名log.6到log.7,然后是log.5到log.6,依此类推。当前log变成log.0,并且Squid创建一个新的空文件,命名为log。

每次执行squid -k rotate时,Squid轮转下述文件:cache.log, access.log, store.log, useragent.log (假如激活), 以及referer.log (假如激活)。Squid也会创建最新版本的swap.state文件。然而请注意,swap.state不会以数字扩展形式来轮转。

Squid不会自己轮转日志,最好的办法是在crontab里自动执行。例如:

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

假如你想编写自己的脚本来管理日志文件,Squid提供了一个有用的模式,简单的设置logfile_rotate指令为0。这样,当你运行squid -k rotate命令时,Squid简单的关闭当前日志文件,并且打开新的。如果操作系统允许重命名被其他进程打开的文件,则这点非常有用。下述shell脚本描述了一个思路:

#!/bin/sh

set -e

yesterday_secs=`perl -e 'print time -43200'`

yesterday_date=`date -r $yesterday_secs +%Y%m%d`

cd /usr/local/squid/var/logs

# rename the current log file without interrupting the logging process

mv access.log access.log.$yesterday_date

# tell Squid to close the current logs and open new ones

/usr/local/squid/sbin/squid -k rotate

# give Squid some time to finish writing swap.state files

sleep 60

mv access.log.$yesterday_date /archive/location/

    gzip -9 /archive/location/access.log.$yesterday_date


13.8 隐私和安全

Squid的日志文件特别是access.log,包含了用户的活跃记录,因此它受隐私问题支配。作为Squid管理员,你必须采取额外的小心来保证日志文件安全。最好的办法是限制访问Squid主机的人员的数量。假如这点行不通,那么就要谨慎的检查文件和目录许可,确保日志文件不会被非信任的、或未授权的用户访问。

也可利用client_netmask和strip_query_terms指令来保护用户隐私。前者让识别access.log里的用户困难;后者移除了URI查询条件以避免泄露用户私人信息。更多信息见13.2.4节。

如果想要保持历史数据相当长的时间,你也许可裁减日志来保证日志文件匿名。假如你仅对哪个URI被访问感兴趣,而不是谁访问了它们,就可从access.log里抽取出该域。这样也让文件更小,并且减少了隐私违背的风险。另一个技术是随机处理客户端IP地址。换句话说,就是创建一个过滤器,把真正的IP地址映射到假的地址,前提是同一个真IP地址总是映射到同一个假IP。假如你在使用RFC 1413身份验证协议或HTTP认证,也可考虑保持这些域匿名。