[squid-users] SMP mode fails to process sibling icp hits from peer

JoeM joe.mozdzer at gmail.com
Tue Feb 7 18:11:12 UTC 2017 

I am running squid 3.5.23 in accelerator mode with a sibling and have
recently enabled SMP mode with multiple workers.  Since I have done this, I
have noticed that squid  will only fetch content from the sibling if the ICP
response was processed by the same worker which handled the original client
request.   (With the workers line omitted I have not seen the problem).   Is
this a known issue with SMP mode or maybe I am overlooking something that I
need I my config?   Any ideas would be appreciated.
Thanks,
Joe

Here are the parts of my config that I believe may be relevant (as seen by
cachemgr.cgi):

workers 2
http_port [::]:80 accel vhost name=80 connection-auth=on
cache_peer 127.0.0.1 Parent 1114 0 name=cachemgr no-digest originserver
connection-auth=auto
cache_peer 172.22.2.135 Sibling 80 3130 name=peer2 no-digest allow-miss
originserver forceddomain=172.22.2.135 connection-auth=auto

memory_cache_shared on
minimum_object_size 0 bytes
maximum_object_size 33554432 bytes
cache_dir rock /lvm/cache/squid

collapsed_forwarding on
icp_port 3130
icp_query_timeout 500


Here is a successful case of retrieving a file "test6.txt" from a peer. 
Kid1 handled both the original request and the processing of the icp reply
in this case:

2017/02/07 16:45:57.666 kid1| 44,3| peer_select.cc(137) peerSelect:
e:t6035=WV/0x7f5f73241080*2 http://172.22.2.76/test6.txt
2017/02/07 16:45:57.666 kid1| 44,3| peer_select.cc(441) peerSelectFoo: GET
172.22.2.76
2017/02/07 16:45:57.666 kid1| 44,3| peer_select.cc(464) peerSelectFoo:
peerSelectFoo: direct = DIRECT_NO (forced non-direct)
2017/02/07 16:45:57.666 kid1| 44,3| peer_select.cc(477) peerSelectFoo:
peerSelectFoo: direct = DIRECT_NO
2017/02/07 16:45:57.666 kid1| 15,5| neighbors.cc(759) peerDigestLookup:
peerDigestLookup: peer 172.22.2.135
2017/02/07 16:45:57.666 kid1| 15,5| neighbors.cc(763) peerDigestLookup:
peerDigestLookup: gone!
2017/02/07 16:45:57.666 kid1| 15,5| neighbors.cc(759) peerDigestLookup:
peerDigestLookup: peer 127.0.0.1
2017/02/07 16:45:57.666 kid1| 15,5| neighbors.cc(763) peerDigestLookup:
peerDigestLookup: gone!
2017/02/07 16:45:57.666 kid1| 15,4| neighbors.cc(847) neighborsDigestSelect:
neighborsDigestSelect: choices: 0 (0)
2017/02/07 16:45:57.666 kid1| 15,4| neighbors.cc(867) peerNoteDigestLookup:
peerNoteDigestLookup: peer <none>, lookup: LOOKUP_NONE
2017/02/07 16:45:57.666 kid1| 44,3| peer_select.cc(110) peerSelectIcpPing:
peerSelectIcpPing: http://172.22.2.76/test6.txt
2017/02/07 16:45:57.666 kid1| 15,3| neighbors.cc(289) neighborsCount:
neighborsCount: 1
2017/02/07 16:45:57.666 kid1| 44,3| peer_select.cc(121) peerSelectIcpPing:
peerSelectIcpPing: counted 1 neighbors
2017/02/07 16:45:57.666 kid1| 44,3| peer_select.cc(587) peerGetSomeNeighbor:
peerSelect: Doing ICP pings
2017/02/07 16:45:57.666 kid1| 15,5| neighbors.cc(626) neighborsUdpPing:
neighborsUdpPing: Peer 172.22.2.135
2017/02/07 16:45:57.666 kid1| 15,4| neighbors.cc(633) neighborsUdpPing:
neighborsUdpPing: pinging peer 172.22.2.135 for
'http://172.22.2.76/test6.txt'
2017/02/07 16:45:57.666 kid1| 15,3| neighbors.cc(635) neighborsUdpPing:
neighborsUdpPing: key = '68E702FD5914605C2B70B9A015BDCF7B'
2017/02/07 16:45:57.666 kid1| 15,3| neighbors.cc(637) neighborsUdpPing:
neighborsUdpPing: reqnum = 12
2017/02/07 16:45:57.666 kid1| 12,5| icp_v2.cc(286) icpUdpSend: icpUdpSend:
FD 31 sending ICP_QUERY, 53 bytes to 172.22.2.135:3130
2017/02/07 16:45:57.666 kid1| 15,5| neighbors.cc(626) neighborsUdpPing:
neighborsUdpPing: Peer 127.0.0.1
2017/02/07 16:45:57.666 kid1| 44,3| peer_select.cc(600) peerGetSomeNeighbor:
peerSelect: 1 ICP replies expected, RTT 500 msec
2017/02/07 16:45:57.667 kid1| 12,4| icp_v2.cc(621) icpHandleUdp:
icpHandleUdp: FD 31: received 49 bytes from 172.22.2.135:3130
2017/02/07 16:45:57.667 kid1| 12,3| icp_v2.cc(503) handleReply:
icpHandleIcpV2: ICP_HIT from 172.22.2.135:3130 for
'http://172.22.2.76/test6.txt'
2017/02/07 16:45:57.667 kid1| 15,6| neighbors.cc(1001) neighborsUdpAck:
neighborsUdpAck: opcode 2 '68E702FD5914605C2B70B9A015BDCF7B'
2017/02/07 16:45:57.667 kid1| 15,3| neighbors.cc(100) whichPeer: whichPeer:
from 172.22.2.135:3130
2017/02/07 16:45:57.667 kid1| 15,3| neighbors.cc(1050) neighborsUdpAck:
neighborsUdpAck: ICP_HIT for '68E702FD5914605C2B70B9A015BDCF7B' from
172.22.2.135 
2017/02/07 16:45:57.667 kid1| 44,3| peer_select.cc(823) peerHandleIcpReply:
peerHandleIcpReply: ICP_HIT http://172.22.2.76/test6.txt
2017/02/07 16:45:57.667 kid1| 44,3| peer_select.cc(441) peerSelectFoo: GET
172.22.2.76
2017/02/07 16:45:57.667 kid1| 44,3| peer_select.cc(655)
peerGetSomeNeighborReplies: peerSelect: SIBLING_HIT/172.22.2.135
2017/02/07 16:45:57.667 kid1| 44,5| peer_select.cc(938) peerAddFwdServer:
peerAddFwdServer: adding 172.22.2.135 SIBLING_HIT


Now here is an example of the failure case for file "test8.txt".   In this
case, kid1 processed the original client request but kid2 is trying to
handle the ICP reply from 172.22.2.135 and can't seem to match it up with
the original request.

2017/02/07 16:53:24.757 kid1| 44,3| peer_select.cc(137) peerSelect:
e:t15793=WV/0x7f5f72fbb660*2 http://172.22.2.76/test8.txt
2017/02/07 16:53:24.757 kid1| 44,3| peer_select.cc(441) peerSelectFoo: GET
172.22.2.76
2017/02/07 16:53:24.757 kid1| 44,3| peer_select.cc(464) peerSelectFoo:
peerSelectFoo: direct = DIRECT_NO (forced non-direct)
2017/02/07 16:53:24.757 kid1| 44,3| peer_select.cc(477) peerSelectFoo:
peerSelectFoo: direct = DIRECT_NO
2017/02/07 16:53:24.757 kid1| 15,5| neighbors.cc(759) peerDigestLookup:
peerDigestLookup: peer 172.22.2.135
2017/02/07 16:53:24.757 kid1| 15,5| neighbors.cc(763) peerDigestLookup:
peerDigestLookup: gone!
2017/02/07 16:53:24.757 kid1| 15,5| neighbors.cc(759) peerDigestLookup:
peerDigestLookup: peer 127.0.0.1
2017/02/07 16:53:24.757 kid1| 15,5| neighbors.cc(763) peerDigestLookup:
peerDigestLookup: gone!
2017/02/07 16:53:24.757 kid1| 15,4| neighbors.cc(847) neighborsDigestSelect:
neighborsDigestSelect: choices: 0 (0)
2017/02/07 16:53:24.757 kid1| 15,4| neighbors.cc(867) peerNoteDigestLookup:
peerNoteDigestLookup: peer <none>, lookup: LOOKUP_NONE
2017/02/07 16:53:24.757 kid1| 44,3| peer_select.cc(110) peerSelectIcpPing:
peerSelectIcpPing: http://172.22.2.76/test8.txt
2017/02/07 16:53:24.757 kid1| 15,3| neighbors.cc(289) neighborsCount:
neighborsCount: 1
2017/02/07 16:53:24.757 kid1| 44,3| peer_select.cc(121) peerSelectIcpPing:
peerSelectIcpPing: counted 1 neighbors
2017/02/07 16:53:24.757 kid1| 44,3| peer_select.cc(587) peerGetSomeNeighbor:
peerSelect: Doing ICP pings
2017/02/07 16:53:24.757 kid1| 15,5| neighbors.cc(626) neighborsUdpPing:
neighborsUdpPing: Peer 172.22.2.135
2017/02/07 16:53:24.758 kid1| 15,4| neighbors.cc(633) neighborsUdpPing:
neighborsUdpPing: pinging peer 172.22.2.135 for
'http://172.22.2.76/test8.txt'
2017/02/07 16:53:24.758 kid1| 15,3| neighbors.cc(635) neighborsUdpPing:
neighborsUdpPing: key = '6ED0B5DA445590DD432D23A0AA190583'
2017/02/07 16:53:24.758 kid1| 15,3| neighbors.cc(637) neighborsUdpPing:
neighborsUdpPing: reqnum = 18
2017/02/07 16:53:24.758 kid1| 12,5| icp_v2.cc(286) icpUdpSend: icpUdpSend:
FD 31 sending ICP_QUERY, 53 bytes to 172.22.2.135:3130
2017/02/07 16:53:24.758 kid1| 15,5| neighbors.cc(626) neighborsUdpPing:
neighborsUdpPing: Peer 127.0.0.1
2017/02/07 16:53:24.758 kid1| 44,3| peer_select.cc(600) peerGetSomeNeighbor:
peerSelect: 1 ICP replies expected, RTT 500 msec
2017/02/07 16:53:24.758 kid2| 12,4| icp_v2.cc(621) icpHandleUdp:
icpHandleUdp: FD 31: received 49 bytes from 172.22.2.135:3130
2017/02/07 16:53:24.758 kid2| 12,3| icp_v2.cc(503) handleReply:
icpHandleIcpV2: ICP_HIT from 172.22.2.135:3130 for
'http://172.22.2.76/test8.txt'
2017/02/07 16:53:24.758 kid2| 15,6| neighbors.cc(1001) neighborsUdpAck:
neighborsUdpAck: opcode 2 '00000000000000000000000000000000'
2017/02/07 16:53:24.758 kid2| 15,3| neighbors.cc(100) whichPeer: whichPeer:
from 172.22.2.135:3130
2017/02/07 16:53:24.758 kid2| 12,3| neighbors.cc(1019) neighborsUdpAck:
neighborsUdpAck: Cache key '00000000000000000000000000000000' not found
2017/02/07 16:53:25.259 kid1| 44,3| peer_select.cc(756) peerPingTimeout:
peerPingTimeout: 'http://172.22.2.76/test8.txt'




--
View this message in context: http://squid-web-proxy-cache.1019090.n4.nabble.com/SMP-mode-fails-to-process-sibling-icp-hits-from-peer-tp4681494.html
Sent from the Squid - Users mailing list archive at Nabble.com.

More information about the squid-users mailing list