[squid-users] Re: Squid: 3.HEAD giving error msgs and exiting with assertion failed:forward.cc:163:"err"

Relevant portion of cache.log when debugging with "debug_options 17
10" in squid.conf as 17 refers to forwarding.

2012/10/03 13:37:35.780| forward.cc(943) dispatch:
local=192.168.8.230:3128 remote=192.168.8.211:44183 FD 27 flags=1:
Fetching 'POST http://www.facebook.com/ajax/proxy.php'
2012/10/03 13:37:35.780| leaving
fwdConnectDoneWrapper(local=192.168.8.230:40309
remote=173.252.101.16:80 FD 296 flags=1, data=0x27076e8)
2012/10/03 13:37:36.566| forward.cc(348) unregister:
http://www.facebook.com/ajax/proxy.php
2012/10/03 13:37:36.566| forward.cc(373) complete:
http://www.facebook.com/ajax/proxy.php
    status 200
2012/10/03 13:37:36.566| forward.cc(1070) reforward:
http://www.facebook.com/ajax/proxy.php?
2012/10/03 13:37:36.566| forward.cc(1073) reforward: No,
ENTRY_FWD_HDR_WAIT isn't set
2012/10/03 13:37:36.566| forward.cc(397) complete: server (FD closed)
not re-forwarding status 200
2012/10/03 13:37:36.567| forward.cc(180) ~FwdState: FwdState destructor starting
2012/10/03 13:37:36.567| forward.cc(210) ~FwdState: FwdState destructor done
2012/10/03 13:37:42.100| ConnOpener.cc(129) will call
fwdConnectDoneWrapper(local=192.168.8.230:56671
remote=74.125.236.128:443 FD 130 flags=1, data=0x28805d8) [call17556]
2012/10/03 13:37:42.101| entering
fwdConnectDoneWrapper(local=192.168.8.230:56671
remote=74.125.236.128:443 FD 130 flags=1, data=0x28805d8)
2012/10/03 13:37:42.101| AsyncCall.cc(34) make: make call
fwdConnectDoneWrapper [call17556]
2012/10/03 13:37:42.101| forward.cc(754) connectDone:
local=192.168.8.230:56671 remote=74.125.236.128:443 FD 130 flags=1:
'https://plus.google.com/u/0/_/n/gcosuc?origin=https%3A%2F%2Fwww.google.com.pk'
2012/10/03 13:37:42.101| leaving
fwdConnectDoneWrapper(local=192.168.8.230:56671
remote=74.125.236.128:443 FD 130 flags=1, data=0x28805d8)
2012/10/03 13:37:43.068| forward.cc(535) serverClosed: FD -1
https://plus.google.com/u/0/_/n/gcosuc?origin=https%3A%2F%2Fwww.google.com.pk
2012/10/03 13:37:43.069| forward.cc(180) ~FwdState: FwdState destructor starting
2012/10/03 13:37:43.069| assertion failed: forward.cc:163: "err"

On Wed, Oct 3, 2012 at 12:55 PM, Ahmed Talha Khan <auny87_at_gmail.com> wrote:
> Hey All, Amons,
>
> I just looked deeper in the issue. gdb gives me the following bt
>
> (gdb) bt
> #0 0x00007ffff66a73a5 in raise () from /lib/x86_64-linux-gnu/libc.so.6
> #1 0x00007ffff66aab0b in abort () from /lib/x86_64-linux-gnu/libc.so.6
> #2 0x0000000000516745 in xassert (msg=0x6fe1a4 "err", file=<optimized
> out>, line=163) at debug.cc:567
> #3 0x000000000052c39a in FwdState::completed (this=0x10a59b8) at forward.cc:163
> #4 0x000000000052ec21 in FwdState::~FwdState (this=0x10a59b8,
> __in_chrg=<optimized out>, __vtt_parm=<optimized out>) at
> forward.cc:183
> #5 0x000000000052f189 in FwdState::~FwdState (this=0x10a59b8,
> __in_chrg=<optimized out>, __vtt_parm=<optimized out>) at
> forward.cc:211
> #6 0x00000000005321a3 in dereference (newP=0x0, this=0x10a59d0) at
> ../include/RefCount.h:96
> #7 operator= (p=..., this=0x10a59d0) at ../include/RefCount.h:64
> #8 FwdState::retryOrBail (this=0x10a59b8) at forward.cc:561
> #9 0x0000000000620be4 in AsyncCall::make (this=0x116b670) at AsyncCall.cc:36
> #10 0x0000000000623c37 in AsyncCallQueue::fireNext (this=<optimized
> out>) at AsyncCallQueue.cc:54
> #11 0x0000000000623d90 in AsyncCallQueue::fire (this=0xaf6840) at
> AsyncCallQueue.cc:40
> #12 0x00000000005246bc in EventLoop::runOnce (this=0x7fffffffe080) at
> EventLoop.cc:131
> #13 0x0000000000524788 in EventLoop::run (this=0x7fffffffe080) at
> EventLoop.cc:95
> #14 0x000000000057d8a1 in SquidMain (argc=<optimized out>,
> argv=<optimized out>) at main.cc:1503
> #15 0x00000000004cc026 in SquidMainSafe (argv=<optimized out>,
> argc=<optimized out>) at main.cc:1218
> #16 main (argc=<optimized out>, argv=<optimized out>) at main.cc:1210
>
>
> Looking at frame # 3 above i get the following information:
>
> (gdb) print this.entry.store_status
> $7 = STORE_PENDING
>
> $18 = {<StoreEntry> = {<_hash_link> = {key = 0x1030370, next = 0x0},
> _vptr.StoreEntry = 0x709d10, mem_obj = 0x1051b70, hidden_mem_obj =
> 0x0,
> repl = {data = 0x0}, timestamp = -1, lastref = 1349245583, expires
> = -1, lastmod = -1, swap_file_sz = 0, refcount = 1, flags = 1440,
> swap_filen = -1, swap_dirn = -1, lock_count = 2, mem_status =
> NOT_IN_MEMORY, ping_status = PING_DONE, store_status = STORE_PENDING,
> swap_status = SWAPOUT_NONE, static pool = 0xf2d970,
> deferredProducer = {p_ = 0x0}}, static _instance = {<StoreEntry> =
> {<_hash_link> = {
> key = 0x0, next = 0x0}, _vptr.StoreEntry = 0x709df0, mem_obj =
> 0x0, hidden_mem_obj = 0x0, repl = {data = 0x0}, timestamp = -1,
> lastref = -1, expires = -1, lastmod = -1, swap_file_sz = 0,
> refcount = 0, flags = 0, swap_filen = -1, swap_dirn = -1, lock_count =
> 0,
> mem_status = NOT_IN_MEMORY, ping_status = PING_NONE,
> store_status = STORE_OK, swap_status = SWAPOUT_NONE, static pool =
> 0xf2d970,
> deferredProducer = {p_ = 0x0}}, static _instance = <same as
> static member of an already seen type>}}
>
>
> (gdb) print *(StoreEntry*)this.entry
> $19 = {<_hash_link> = {key = 0x1030370, next = 0x0}, _vptr.StoreEntry
> = 0x709d10, mem_obj = 0x1051b70, hidden_mem_obj = 0x0, repl = {data =
> 0x0},
> timestamp = -1, lastref = 1349245583, expires = -1, lastmod = -1,
> swap_file_sz = 0, refcount = 1, flags = 1440, swap_filen = -1,
> swap_dirn = -1,
> lock_count = 2, mem_status = NOT_IN_MEMORY, ping_status = PING_DONE,
> store_status = STORE_PENDING, swap_status = SWAPOUT_NONE,
> static pool = 0xf2d970, deferredProducer = {p_ = 0x0}}
>
>
> I see that some kind of entry is pending and squid is not able to
> complete it hence it exists itself. Can anybody help in this case.
> What are these entries related to.
>
>
>
> On Thu, Sep 27, 2012 at 3:31 PM, Ahmed Talha Khan <auny87_at_gmail.com> wrote:
>> Hey All,
>>
>> Using squid.3.HEAD.20120421-r12120 on linux Ubuntu i am getting the
>> following error and squid exits
>>
>> 2012/09/27 13:03:12| Starting Squid Cache version
>> 3.HEAD-20120421-r12120 for x86_64-unknown-linux-gnu...
>> 2012/09/27 13:03:12| Process ID 4729
>> 2012/09/27 13:03:12| Process Roles: master worker
>> 2012/09/27 13:03:12| With 200000 file descriptors available
>> 2012/09/27 13:03:12| Initializing IP Cache...
>> 2012/09/27 13:03:12| DNS Socket created at [:(inlove), FD 5
>> 2012/09/27 13:03:12| DNS Socket created at 0.0.0.0, FD 6
>> 2012/09/27 13:03:12| Adding nameserver 208.67.222.222 from /etc/resolv.conf
>> 2012/09/27 13:03:12| Adding nameserver 8.8.8.8 from /etc/resolv.conf
>> 2012/09/27 13:03:12| helperOpenServers: Starting 5/32 'ssl_crtd' processes
>> 2012/09/27 13:03:13| Logfile: opening log
>> daemon:/usr/local/squid/var/logs/access.log
>> 2012/09/27 13:03:13| Logfile Daemon: opening log
>> /usr/local/squid/var/logs/access.log
>> 2012/09/27 13:03:13| Logfile: opening log /usr/local/squid/var/logs/icap-log
>> 2012/09/27 13:03:13| WARNING: log parameters now start with a module
>> name. Use 'stdio:/usr/local/squid/var/logs/icap-log'
>> 2012/09/27 13:03:13| Store logging disabled
>> 2012/09/27 13:03:13| Swap maxSize 0 + 262144 KB, estimated 20164 objects
>> 2012/09/27 13:03:13| Target number of buckets: 1008
>> 2012/09/27 13:03:13| Using 8192 Store buckets
>> 2012/09/27 13:03:13| Max Mem size: 262144 KB
>> 2012/09/27 13:03:13| Max Swap size: 0 KB
>> 2012/09/27 13:03:13| Using Least Load store dir selection
>> 2012/09/27 13:03:13| Set Current Directory to /usr/local/squid/var/cache
>> 2012/09/27 13:03:13| Loaded Icons.
>> 2012/09/27 13:03:13| HTCP Disabled.
>> 2012/09/27 13:03:13| /usr/local/squid/var/run/squid.pid: (13) Permission denied
>> 2012/09/27 13:03:13| WARNING: Could not write pid file
>> 2012/09/27 13:03:13| Squid plugin modules loaded: 0
>> 2012/09/27 13:03:13| Adaptation support is on
>> 2012/09/27 13:03:13| Accepting SSL bumped HTTP Socket connections at
>> local=127.0.0.1:3128 remote=[:(inlove) FD 20 flags=9
>> 2012/09/27 13:03:13| Accepting SSL bumped HTTPS Socket connections at
>> local=127.0.0.1:3129 remote=[:(inlove) FD 21 flags=9
>> 2012/09/27 13:03:14| storeLateRelease: released 0 objects
>> 2012/09/27 13:05:2 BUG: Orphan Comm::Connection:
>> local=192.168.8.221:54062 remote=74.125.236.135:443 FD 41 flags=1
>> 2012/09/27 13:05:2 NOTE: 1 Orphans since last started.
>> 2012/09/27 13:06:29| BUG: Orphan Comm::Connection:
>> local=192.168.8.221:46538 remote=74.125.236.136:443 FD 12 flags=1
>> 2012/09/27 13:06:29| NOTE: 2 Orphans since last started.
>> 2012/09/27 13:07:30| BUG: Orphan Comm::Connection:
>> local=192.168.8.221:33706 remote=74.125.236.134:443 FD 8 flags=1
>> 2012/09/27 13:07:30| NOTE: 3 Orphans since last started.
>> 2012/09/27 13:08:2 assertion failed: forward.cc:163: "err"
>> Aborted
>>
>> What are the these ORPHAN msgs related to ? Also how can i resolve the
>> assertion failed problem. Kindly explain what you suggest. Thanks
>>
>>
>> --
>> Regards,
>> -Ahmed Talha Khan
>
>
>
> --
> Regards,
> -Ahmed Talha Khan

-- 
Regards,
-Ahmed Talha Khan