Squid日志中为何会有HIT，并且DIRECT的记录？

dewly_tg

　　http://blog.iyunv.com/uid-8474831-id-3467954.html
　　

前几天，@ARGV问了这个问题《squid 灵异日志》

http://chenlinux.com/2010/03/17/problem-of-squid-access-log/

灵异乎？一般灵异吧。只要我们走近科学，没有什么不能被解释的。

首先说一下HIT/MISS/REFRESH_HIT这些状态是由什么决定的

其实这些状态，在代码里就是http->log_type。而这个log_type的赋值主要是这么几个地方：

第一处，clientProcessRequest中

　　点击(此处)折叠或打开

• http->log_type = clientProcessRequest2(http);
  

简单地说，找到了要访问的entry，就是TCP_HIT，没找到就是TCP_MISS。

第二处，clientAccessCheckDone中，如果http_access检查没有通过，设成TCP_DENIED

第三处，clientHandleIMSReply中，根据回源IMS校验结果，可能设置成TCP_REFRESH_HIT或者TCP_REFRESH_MISS

第四处，clientCacheHit中，可能由于打开/读取磁盘文件失败，设成TCP_SWAPFAIL_MISS，也有可能由于缓存了404等报错，设成TCP_NEGATIVE_HIT，或者异步刷新的原因，设成TCP_STALE_HIT，以及由于offline模式的开启，设成TCP_OFFLINE_HIT

第五处，clientProcessHit中，应答客户端的IMS，设成TCP_IMS_HIT，或者由于hit的object的store_status还不是STORE_OK，设成TCP_MISS。

再说一下这个DIRECT是哪里来的。这是http->request->hier。一般来说，没有回源就是HIER_NONE，走DNS回源的时候设成HIER_DIRECT。如果squid里面配置了peer的话，还可能是各种PARENT，或者SIBLING。

那么，一个没有回源的请求，为什么是DIRECT呢？这是因为，虽然这个请求找到了StoreEntry因而没有回源，但是这个找到的StoreEntry是由上一个请求引起回源的，而且回源还没有完成，那么clientProcessRequest里面会修改当前http->request->hier，改成真正引起回源那个请求（也就是http->entry->mem_obj->request）的hier。下面这段代码就是做这件事情的（省略了无关代码）

　　点击(此处)折叠或打开

• if (NULL != http->entry) {
  
• 
  
•          if (http->entry->store_status == STORE_PENDING && http->entry->mem_obj)
  
• 
  
•          {
  
• 
  
•                   if (http->entry->mem_obj->request)
  
• 
  
•                   {
  
• 
  
•                           r->hier = http->entry->mem_obj->request2->hier;
  
• 
  
•                   }
  
• 
  
•          }
  
• 
  
• }
  

如果是这样，按理说，只要是第一个请求回源期间，所有的请求都应该是HIT并且DIRECT才对，应该有很多的HIT/DIRECT才对。而实际上日志中的HIT/DIRECT并不多，这又是为什么呢？

原来，是刚才提到的log_type的第五处修改“clientProcessHit中，由于hit的object的store_status还不是STORE_OK，设成TCP_MISS”造成的。下面是代码

　　点击(此处)折叠或打开

• if (e->store_status != STORE_OK)
  
• 
  
• {
  
• 
  
•          http->log_type = LOG_TCP_MISS;
  
• 
  
• }
  

所以，很多本来是HIT，而hier又被改成了初始回源的请求的hier的请求，log_type被改回了MISS。

接下来是亮点：

不难推断，只要 修改hier的clientProcessRequest，到将HIT改成MISS的clientProcessHit之间，store_status突然由STORE_PENDING变成STORE_OK，就可能会产生HIT/DIRECT了。

这个突变会不会发生呢？

答案是会的。

首先从理论上，clientProcessHit是有clientProcessRequest调用storeClientCopy，然后回调到clientCacheHit，再调到clientProcessHit的，在storeClientCopy期间，所需的header可能在磁盘上，需要进入aufs的异步读取流程，再由aufs的回调调用clientCacheHit。这期间clientProcessRequest会暂时放弃主进程的控制权，这期间StoreEntry完全有机会变成STORE_OK（通过storeComplete函数）。

接下来，我们从日志上验证了这一点，首先在修改hier的代码中加入日志。那句debug(0, 0)会把http结构的地址记入cache.log

　　点击(此处)折叠或打开

• if (http->entry->mem_obj->request2)
  
• 
  
• {
  
• 
  
•          r->hier = http->entry->mem_obj->request2->hier;
  
• 
  
•          debug(0, 0)("passing hier to %p from %p, at %p\n", r, http->entry->mem_obj->request2, http);
  
• 
  
• }
  

然后在HIT改MISS的地方加入日志，如果改了或者没改，都会记录http结构的地址。

　　点击(此处)折叠或打开

• if (e->store_status != STORE_OK)
  
• 
  
•     {
  
• 
  
•         http->log_type = LOG_TCP_MISS;
  
• 
  
•         debug(0, 0)("falling back to TCP_MISS %p\n", http);
  
• 
  
•     }
  
• 
  
•     else if (http->log_type == LOG_TCP_HIT && e->mem_status == IN_MEMORY)
  
• 
  
•     {
  
• 
  
•         http->log_type = LOG_TCP_MEM_HIT;
  
• 
  
•         debug(0, 0)("not falling back to TCP_MISS %p\n", http);
  
• 
  
•     }
  
• 
  
•     else
  
• 
  
•     {
  
• 
  
•         debug(0, 0)("not falling back to TCP_MISS %p\n", http);
  
• 
  
•     }
  

GC来了，我们用ab打一个url，然后看cache.log

绝大部分改了hier的请求，都改回了MISS

　　点击(此处)折叠或打开

• 2013/01/09 14:53:45| passing hier to 0x5fe5170 from 0x5e4bf80, at 0x5fe4d28
  
• 2013/01/09 14:53:45| falling back to TCP_MISS 0x5fe4d28
  

但是，有的请求，由于store_status变了，就没有改回MISS

　　点击(此处)折叠或打开

• 2013/01/09 15:22:47| passing hier to 0x7831910 from 0x7501f80, at 0x78314c8
  
• 2013/01/09 15:22:47| not falling back to TCP_MISS 0x78314c8
  

这时再看访问日志，确实出现了HIT并且DIRECT

　　点击(此处)折叠或打开

• 1357716167 127.0.0.1 - - [09/Jan/2013:15:22:47 +0800] "GET http://127.0.1.4:8080/1.html?49123 HTTP/1.0" 200 3157 "-" "ApacheBench/2.3" TCP_HIT DIRECT
  

小小地总结一下

这个问题是squid一个小bug，不会引起太大的不良后果，只是日志记得诡异了一些，但回源次数不会变多，因此不用担心。