assertion error when rotating logs

[Jean-Baptiste Lallement]

automated crash report

ProblemType: Crash
DistroRelease: Ubuntu 18.10
Package: squid 4.1-1ubuntu2
ProcVersionSignature: Ubuntu 4.18.0-7.8-generic 4.18.5
Uname: Linux 4.17.0-9-generic x86_64
NonfreeKernelModules: binder_linux ashmem_linux
ApportVersion: 2.20.10-0ubuntu11
Architecture: amd64
Date: Sun Sep 23 10:33:59 2018
ExecutablePath: /usr/sbin/squid
InstallationDate: Installed on 2014-07-15 (1534 days ago)
InstallationMedia: Ubuntu 14.10 "Utopic Unicorn" - Alpha amd64 (20140520)
ProcCmdline: (squid-1) --kid squid-1 -sYC
Signal: 6
SourcePackage: squid
StacktraceTop:
 ?? ()
 ?? ()
 comm_openex(int, int, Ip::Address&, int, char const*) ()
 ipcCreate(int, char const*, char const* const*, char const*, Ip::Address&, int*, int*, void**) ()
 IcmpSquid::Open() ()
Title: squid crashed with SIGABRT in comm_openex()
UpgradeStatus: Upgraded to cosmic on 2018-03-24 (186 days ago)
UserGroups:

[Apport retracing service (apport)]

StacktraceTop:
 xassert (msg=msg@entry=0x555e7628ad6f "!isOpen(conn->fd)", file=file@entry=0x555e7628ad3c "comm.cc", line=line@entry=428) at debug.cc:618
 comm_init_opened (conn=..., note=note@entry=0x555e7629a065 "Pinger Socket", AI=0x555e76fe78a0) at comm.cc:428
 comm_openex (sock_type=<optimized out>, proto=<optimized out>, addr=..., flags=2, note=0x555e7629a065 "Pinger Socket") at comm.cc:403
 ipcCreate (type=type@entry=2, prog=0x555e76fe8d20 "/usr/lib/squid/pinger", args=args@entry=0x7ffc18daf380, name=name@entry=0x555e7629a065 "Pinger Socket", local_addr=..., rfd=rfd@entry=0x7ffc18daf378, wfd=0x7ffc18daf37c, hIpc=0x555e764f2c28 <_ZL4hIpc>) at ipc.cc:111
 IcmpSquid::Open (this=0x555e764f0ba0 <icmpEngine>) at IcmpSquid.cc:212

[Robie Basak (racb)]

Thank you for the report.

I see that 4.2 is released upstream, but I don't see any related changes upstream in this area (from a quick glance only).

[Adam Conrad (adconrad)]

Getting this crash regularly here too.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Amos Jeffries (yadi)]

IIRC this may be the result of a bug found in the src/ipc/TypedMsgHeader.* GCC-8 patch for 4.1. Debian received the fix for that in the GCC-8 changes formally accepted into 4.2.

[Andreas Hasenack (ahasenack)]

I'll work on an ubuntu update

[Andreas Hasenack (ahasenack)]

Here are squid 4.2 packages for cosmic, merged from debian:

https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/3450/

If the crash happens frequently, would you mind giving these packages a try to see if it improves the situation?

They also passed dep8 tests: https://bileto.ubuntu.com/excuses/3450/cosmic.html

[Andreas Hasenack (ahasenack)]

@jibel, are you running squid-deb-proxy too by any chance?

Could you also attach /var/log/squid/cache.log, and perhaps a sanitized /var/log/squid/access.log if you see something interesting in there around the time of the crash?

[Jean-Baptiste Lallement (jibel)]

I'm also running squid-deb-proxy but it's the main squid that crashed. Here is the cache.log from the time of the crash. The access file for the same time is empty (I don't use squid on this machine at the moment)

[Andreas Hasenack (ahasenack)]

Do you still have /var/log/syslog (maybe rotated) from the time of the crash, september 23rd? If yes, please attach it. Maybe I can correlate it with something else going on in the system.

Is the crash still happening?

[Jean-Baptiste Lallement (jibel)]

Here is the journal with records from September 23rd. The crash happened again yesterday.

[Andreas Hasenack (ahasenack)]

Thanks!

This is interesting. At 10:33:57, looks like this machine came back from sleep/suspend. Is this a laptop?

Then 2s later we have these:
sept. 23 10:33:59 sark audit[12944]: AVC apparmor="DENIED" operation="capable" profile="/usr/sbin/squid" pid=12944 comm="squid" capability=12 capname="net_admin"
sept. 23 10:33:59 sark audit[12944]: AVC apparmor="DENIED" operation="connect" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/squid" name="run/dbus/system_bus_socket" pid=12944 comm="squid" requested_mask="wr" denied_mask="wr" fsuid=0 ouid=0
sept. 23 10:33:59 sark audit[12944]: AVC apparmor="DENIED" operation="connect" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/squid" name="run/dbus/system_bus_socket" pid=12944 comm="squid" requested_mask="wr" denied_mask="wr" fsuid=0 ouid=0
sept. 23 10:33:59 sark audit[12944]: AVC apparmor="DENIED" operation="connect" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/squid" name="run/dbus/system_bus_socket" pid=12944 comm="squid" requested_mask="wr" denied_mask="wr" fsuid=0 ouid=0
sept. 23 10:33:59 sark squid[11655]: Closing Pinger socket on FD 14
sept. 23 10:33:59 sark squid[11655]: storeDirWriteCleanLogs: Starting...
sept. 23 10:33:59 sark squid[11655]: Finished. Wrote 0 entries.
sept. 23 10:33:59 sark squid[11655]: Took 0.00 seconds ( 0.00 entries/sec).
sept. 23 10:33:59 sark squid[11655]: logfileRotate: daemon:/var/log/squid/access.log
sept. 23 10:33:59 sark squid[11655]: logfileRotate: daemon:/var/log/squid/access.log
sept. 23 10:33:59 sark squid[11655]: assertion failed: comm.cc:428: "!isOpen(conn->fd)"

[Andreas Hasenack (ahasenack)]

@jibel and @adconrad, are you guys running squid with its apparmor profile enabled? Can you check with ps faxwZ or aa-status?

[Jean-Baptiste Lallement (jibel)]

apparently so

/usr/sbin/squid (enforce) 1934 ? Ss 0:00 /usr/sbin/squid -sYC
/usr/sbin/squid (enforce) 32043 ? S 0:04 \_ (squid-1) --kid squid-1 -sYC
/usr/sbin/squid (enforce) 32062 ? S 0:00 \_ (logfile-daemon) /var/log/squid/access.log
/usr/sbin/squid (enforce) 32066 ? S 0:01 \_ (pinger)

For reference I never enabled this (or didn't know I did if I did)

[Andreas Hasenack (ahasenack)]

Ok, this seems to be pointing at a problem with the apparmor profile. I'll prepare an update for that.

This is the patch I will be using:
--- etc/apparmor.d/usr.sbin.squid
+++ etc/apparmor.d/usr.sbin.squid
@@ -3,7 +3,7 @@
 # vim:syntax=apparmor
 #include <tunables/global>

-/usr/sbin/squid {
+/usr/sbin/squid flags=(attach_disconnected) {
   #include <abstractions/base>
   #include <abstractions/kerberosclient>
   #include <abstractions/nameservice>
@@ -18,6 +18,7 @@
   # alternatively include the <abstractions/ssl_keys> abstraction, which
   # gives read access to the entire contents of /etc/ssl

+ capability net_admin,
   capability net_raw,
   capability setuid,
   capability setgid,

If you want to try it, please change /etc/apparmor.d/usr.sbin.squid as per above, and reload it with this command:

sudo apparmor_parser -r -T -W /etc/apparmor.d/usr.sbin.squid

[Andreas Hasenack (ahasenack)]

/usr/sbin/squid -k rotate is enough to crash it on adconrad's machine, even with the apparmor profile disabled.

We also tried with the new 4.2 packages, but -k rotate also crashes it the same way.

[Andreas Hasenack (ahasenack)]

This looks very much like https://bugs.squid-cache.org/show_bug.cgi?id=4796

[Andreas Hasenack (ahasenack)]

I also just managed to get this in debian's 4.2-2:
Oct 4 20:17:00 sid-squid4 squid[582]: assertion failed: comm.cc:428: "!isOpen(conn->fd)"

Still working on a solid reproducer, but getting there.

[Andreas Hasenack (ahasenack)]

Turns out it's easier than I thought, both in debian and ubuntu:

lxc launch images:debian/sid sid-squid

lxc exec sid-squid bash

apt update && apt install squid -y

tail -f /var/log/squid/cache.log | grep -1 assert

In another terminal:
lxc exec sid-squid bash
squid -k rotate

Watch the crash in the tail:
root@sid-squid:~# tail -f /var/log/squid/cache.log |grep -1 assert
2018/10/04 20:34:14 kid1| logfileRotate: daemon:/var/log/squid/access.log
2018/10/04 20:34:14 kid1| assertion failed: comm.cc:428: "!isOpen(conn->fd)"
2018/10/04 20:34:15 kid1| Set Current Directory to /var/spool/squid

[Andreas Hasenack (ahasenack)]

If squid.conf has a cache_dir setting, then the crash doesn't happen. For example:
cache_dir aufs /var/cache/squid-deb-proxy 40000 16 256

Or, as I had in my home proxy, which wasn't crashing:
cache_dir ufs /var/spool/squid 10000 16 256

[Andreas Hasenack (ahasenack)]

Disabling the pinger also works around the problem:

In /etc/squid/squid.conf:
pinger_enable off

[Andreas Hasenack (ahasenack)]

Upstream PR got some activity: https://github.com/squid-cache/squid/pull/257

[Launchpad Janitor (janitor)]

This bug was fixed in the package squid - 4.1-1ubuntu3

---------------
squid (4.1-1ubuntu3) cosmic; urgency=medium

  * d/p/fix-rotate-assertion.patch: Fix assertion error when rotating logs.
    Thanks to Vitaly Lavrov <email address hidden>. (LP: #1794553)

 -- Andreas Hasenack <email address hidden> Tue, 09 Oct 2018 14:00:36 -0300