squid3 killed by ABRT signal. assertion failed: disk.cc377: "fd >= 0"

[TJ]

On 12.04 x86 server during start-up.

dmesg shows:

[ 79.073519] init: squid3 main process (3562) killed by ABRT signal

/var/log/squid3/cache.log.1 shows:

$ sudo tail /var/log/squid3/cache.log.1

2012/04/26 11:12:23| Loaded Icons.
2012/04/26 11:12:23| Accepting intercepted HTTP connections at 0.0.0.0:3128, FD 14.
2012/04/26 11:12:23| HTCP Disabled.
2012/04/26 11:12:23| Squid plugin modules loaded: 0
2012/04/26 11:12:23| Adaptation support is off.
2012/04/26 11:12:23| Ready to serve requests.
2012/04/26 11:12:23| Store rebuilding is 3.22% complete
2012/04/26 11:12:24| Reconfiguring Squid Cache (version 3.1.19)...
2012/04/26 11:12:24| FD 14 Closing HTTP connection
2012/04/26 11:12:24| assertion failed: disk.cc:377: "fd >= 0"

In /var/log/syslog

Apr 26 11:12:23 jeeves dnsmasq-dhcp[3636]: DHCP, IP range 10.254.250.2 -- 10.254.250.254, lease time 1d
Apr 26 11:12:23 jeeves dnsmasq-dhcp[3636]: DHCP, IP range 10.254.251.50 -- 10.254.251.254, lease time 1d
Apr 26 11:12:24 jeeves kernel: [ 71.276249] phy0 -> rt2800pci_mcu_status: Error - MCU request failed, no response from hardware
Apr 26 11:12:24 jeeves pptpd[3814]: MGR: connections limit (100) reached, extra IP addresses ignored
Apr 26 11:12:24 jeeves pptpd[3814]: MGR: connections limit (100) reached, extra IP addresses ignored
Apr 26 11:12:24 jeeves pptpd[3815]: MGR: Manager process started
Apr 26 11:12:24 jeeves pptpd[3815]: MGR: Maximum of 100 connections available

I suspect this is related to bug #978356 "squid3 gets killed at startup with dnsmasq and no networkmanager".

It could be that the squid3 resolver script '/etc/resolvconf/update-libc.d/squid3' that caused initctl to reload squid3 when dnsmasq starts and updates '/etc/resolv.conf' causes this.

The service can be successfully restarted manually but that is no solution for an unattended server.

[M-a-young (m-a-young)]

I am running squid 3.1.9 and saw that it had restarted. The error
assertion failed: disk.cc:377: "fd >= 0" was in the cache.log file. There is also a core file, which gives the backtrace
#0 0x00002b5011036265 in raise () from /lib64/libc.so.6
#1 0x00002b5011037d10 in abort () from /lib64/libc.so.6
#2 0x00000000004aa023 in xassert (msg=0x5af417 "fd >= 0",
    file=0x5ac738 "disk.cc", line=377) at debug.cc:556
#3 0x00000000004b5b07 in file_write (fd=0, file_offset=-1,
    ptr_to_buf=0x2aaadd7be700, len=72, handle=0, handle_data=0x0,
    free_func=0x57e730 <FreeObject(void*)>) at disk.cc:377
#4 0x000000000057e88a in UFSSwapDir::logEntry (this=0x1619e150, e=..., op=1)
    at ufs/store_dir_ufs.cc:1052
#5 0x000000000053655a in storeSwapOutFileClosed (data=<value optimized out>,
    errflag=0, self=<value optimized out>) at store_swapout.cc:354
#6 0x0000000000582688 in UFSStoreState::doCloseCallback (this=0x2aaafe3ffaf8,
    errflag=0) at ufs/store_io_ufs.cc:390
#7 0x00000000005806cc in UFSStoreState::closeCompleted (this=0x2aaafe3ffaf8)
    at ufs/store_io_ufs.cc:177
#8 0x0000000000581bf8 in UFSStoreState::openDone (this=0x2aaafe3ffaf8)
    at ufs/store_io_ufs.cc:151
#9 0x000000000058f979 in DiskThreadsDiskFile::openDone (this=0x2aaaaca11c18,
    unused=<value optimized out>, unused2=<value optimized out>,
    anFD=<value optimized out>, errflag=0)
    at DiskIO/DiskThreads/DiskThreadsDiskFile.cc:198
#10 0x000000000058cd3b in DiskThreadsIOStrategy::callback (this=0x93a1a0)
    at DiskIO/DiskThreads/DiskThreadsIOStrategy.cc:149
#11 0x0000000000531dc9 in StoreHashIndex::callback (this=0x16190530)
    at store_dir.cc:743
#12 0x0000000000505395 in StoreRootEngine::checkEvents (
    this=<value optimized out>, timeout=25415) at main.cc:162
#13 0x00000000004be583 in EventLoop::checkEngine (this=0x7fffb4a41190,
    engine=0x7fffb4a41200, primary=6) at EventLoop.cc:48
#14 0x00000000004be6a7 in EventLoop::runOnce (this=0x7fffb4a41190)
    at EventLoop.cc:114
#15 0x00000000004be7f8 in EventLoop::run (this=0x7fffb4a41190)
    at EventLoop.cc:94
#16 0x0000000000504c9f in SquidMain (argc=<value optimized out>,
    argv=0x7fffb4a41318) at main.cc:1400
#17 0x00000000005052a6 in SquidMainSafe (argc=25415, argv=0x6347)
    at main.cc:1160
#18 main (argc=25415, argv=0x6347) at main.cc:1152

[M-a-young (m-a-young)]

I had a couple of occurrences of this with 3.1.9 when doing a squid -k reconfigure
In cache.log the log lines are

2010/12/14 10:34:35| Reconfiguring Squid Cache (version 3.1.9)...
2010/12/14 10:34:35| FD 12 Closing HTTP connection
2010/12/14 10:34:35| assertion failed: disk.cc:377: "fd >= 0"
2010/12/14 10:36:45| Starting Squid Cache version 3.1.9 for x86_64-unknown-linux-gnu...

[M-a-young (m-a-young)]

This has happened again with 3.1.12.1-20110523 after doing squid -k reconfigure. The traceback (below) looks similar.
#0 0x0000003174830265 in raise () from /lib64/libc.so.6
#1 0x0000003174831d10 in abort () from /lib64/libc.so.6
#2 0x00000000004afc23 in xassert (msg=0x5bc317 "fd >= 0",
    file=0x5b9618 "disk.cc", line=377) at debug.cc:556
#3 0x00000000004bb6f8 in file_write (fd=0, file_offset=-1,
    ptr_to_buf=0x326b1c30, len=72, handle=0, handle_data=0x0,
    free_func=0x585900 <FreeObject(void*)>) at disk.cc:377
#4 0x0000000000585a5d in UFSSwapDir::logEntry (this=0x1bd880d0, e=..., op=1)
    at ufs/store_dir_ufs.cc:1049
#5 0x000000000053d1ea in storeSwapOutFileClosed (data=<value optimized out>,
    errflag=0, self=<value optimized out>) at store_swapout.cc:354
#6 0x0000000000589868 in UFSStoreState::doCloseCallback (this=0x2aaab745c938,
    errflag=0) at ufs/store_io_ufs.cc:390
#7 0x00000000005878ac in UFSStoreState::closeCompleted (this=0x2aaab745c938)
    at ufs/store_io_ufs.cc:177
#8 0x0000000000588dd8 in UFSStoreState::openDone (this=0x2aaab745c938)
    at ufs/store_io_ufs.cc:151
#9 0x0000000000596b89 in DiskThreadsDiskFile::openDone (this=0x1c004a68,
    unused=<value optimized out>, unused2=<value optimized out>,
    anFD=<value optimized out>, errflag=0)
    at DiskIO/DiskThreads/DiskThreadsDiskFile.cc:198
#10 0x0000000000593f4b in DiskThreadsIOStrategy::callback (this=0x949620)
    at DiskIO/DiskThreads/DiskThreadsIOStrategy.cc:149
---Type <return> to continue, or q <return> to quit---
#11 0x0000000000538a59 in StoreHashIndex::callback (this=0x1bd6e6a0)
    at store_dir.cc:743
#12 0x000000000050b4e5 in StoreRootEngine::checkEvents (
    this=<value optimized out>, timeout=7174) at main.cc:170
#13 0x00000000004c43e3 in EventLoop::checkEngine (this=0x7fffb695f780,
    engine=0x7fffb695f7f0, primary=6) at EventLoop.cc:48
#14 0x00000000004c4507 in EventLoop::runOnce (this=0x7fffb695f780)
    at EventLoop.cc:114
#15 0x00000000004c4658 in EventLoop::run (this=0x7fffb695f780)
    at EventLoop.cc:94
#16 0x000000000050adef in SquidMain (argc=<value optimized out>,
    argv=0x7fffb695f908) at main.cc:1416
#17 0x000000000050b3f6 in SquidMainSafe (argc=7174, argv=0x1c06)
    at main.cc:1176
#18 main (argc=7174, argv=0x1c06) at main.cc:1168

[Amos Jeffries (yadi)]

*** Bug 2532 has been marked as a duplicate of this bug. ***

[James Page (james-page)]

Marked 'Confirmed' as multiple reports upstream and 'High' - as TJ states 'The service can be successfully restarted manually but that is no solution for an unattended server.'

[Immatix (immatix)]

I can also confirm this exact problem occurring in 12.04 32-Bit, in a server configuration with dnsmasq. Squid is configured to use 127.0.0.1 (dnsmasq) as a name server. dnsmasq is configured with a set of upstream DNS servers.

dmesg:
[ 17.256295] init: squid3 main process (1236) killed by ABRT signal

/var/log/squid3/cache.log:
2012/04/30 00:04:26| HTCP Disabled.
2012/04/30 00:04:26.443| WCCPv1 disabled.
2012/04/30 00:04:26.443| WCCPv2 Disabled.
2012/04/30 00:04:26.443| Squid plugin modules loaded: 0
2012/04/30 00:04:26.443| Adaptation support is off.
2012/04/30 00:04:26.443| Ready to serve requests.
2012/04/30 00:04:26.443| Store rebuilding is 11.49% complete
2012/04/30 00:04:26.443| Reconfiguring Squid Cache (version 3.1.19)...
2012/04/30 00:04:26.443| FD 14 Closing HTTP connection
2012/04/30 00:04:26.443| assertion failed: disk.cc:377: "fd >= 0"

I'm starting squid from /etc/rc.local as a workaround.

[Amos Jeffries (yadi)]

Upstream bug referenced here is about cache storage failures during startup/reconfigure. Which seems a bit at odds with resolv.conf loading errors, although it may be a secondary bug result of the resolv.conf reconfigure action being successfully triggered very early after startup.

A stack trace is required to identify and confirm the code path leading to this crash. To be compared with the traces already available upstream.

[D J Gardner (djgardner)]

My trial patch to solve bug #995523 "squid3 is killed by /etc/resolvconf/update-libc.d/squid3" , now lets this bug be triggered instead.
That bug was caused by squid receiving a HUP before the signal handler has been configured. My patch just moved the HUP handler earlier. Thus a reconfigure as soon as the reconfigure checks start being done.

[D J Gardner (djgardner)]

On the available evidence that this bug is caused by resolvconf reload squid "too soon", I attach a work-around patch.
It delays any resolvconf reload by 30 seconds if it occurs within 200 seconds of boot.
Those numbers might well need tuning on other systems, but the patch has solved the issue for my computer
i.e. squid3 now starts properly.

[Ubuntu Foundations Team Bug Bot (crichton)]

The attachment "Delay resolvconf reload when immediately after boot" of this bug report has been identified as being a patch. The ubuntu-reviewers team has been subscribed to the bug report so that they can review the patch. In the event that this is in fact not a patch you can resolve this situation by removing the tag 'patch' from the bug report and editing the attachment so that it is not flagged as a patch. Additionally, if you are member of the ubuntu-reviewers team please also unsubscribe the team from this bug report.

[This is an automated message performed by a Launchpad user owned by Brian Murray. Please contact him regarding any issues with the action taken in this bug report.]

[Dmitriy Altuhov (altuhovsu)]

This bug also fixed by patch in bug #978356

Jun 23 00:04:44 server kernel: [ 14.922376] init: squid3 main process (1148) killed by ABRT signal
Jun 23 00:04:44 server kernel: [ 14.922405] init: squid3 main process ended, respawning

[Ralf Hildebrandt (ralf-hildebrandt)]

Today I also encountered this bug on a squid -k reconfigure:

...
2012/10/25 11:12:45| urlParse: Illegal hostname 'dreammail.edgesuite..net'
2012/10/25 11:17:09| Reconfiguring Squid Cache (version 3.1.21)...
2012/10/25 11:17:09| FD 271 Closing HTTP connection
2012/10/25 11:17:09| FD 272 Closing ICP connection
2012/10/25 11:17:09| FD 273 Closing SNMP socket
2012/10/25 11:17:09| assertion failed: disk.cc:377: "fd >= 0"

[vsespb (vi1tsr)]

Still experience this problem with latest updates (installed new 12.04 yesterday)

2013/10/06 03:41:08| assertion failed: disk.cc:377: "fd >= 0"

[Amos Jeffries (yadi)]

*** Bug 3652 has been marked as a duplicate of this bug. ***

[Amos Jeffries (yadi)]

Marking as duplicate of 3819 since that report contains a lot of good anaysis of this problem.

*** This bug has been marked as a duplicate of bug 3819 ***

[Amos Jeffries (yadi)]

Upstream fixed this bug in release contained in Bionic.