assertion error when rotating logs

Bug #1794553 reported by Jean-Baptiste Lallement on 2018-09-26
18
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Squid
Unknown
Unknown
squid (Debian)
Confirmed
Unknown
squid (Ubuntu)
High
Andreas Hasenack

Bug Description

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:

Related branches

Jean-Baptiste Lallement (jibel) wrote :

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

Changed in squid (Ubuntu):
importance: Undecided → Medium
summary: - squid crashed with SIGABRT in comm_openex()
+ squid crashed with SIGABRT in xassert()
tags: removed: need-amd64-retrace
information type: Private → Public

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) wrote :

Getting this crash regularly here too.

Launchpad Janitor (janitor) wrote :

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

Changed in squid (Ubuntu):
status: New → Confirmed
Amos Jeffries (yadi) wrote :

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) wrote :

I'll work on an ubuntu update

Changed in squid (Ubuntu):
assignee: nobody → Andreas Hasenack (ahasenack)
status: Confirmed → In Progress
Andreas Hasenack (ahasenack) wrote :

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) wrote :

@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?

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) wrote :

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?

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

Andreas Hasenack (ahasenack) wrote :

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) wrote :

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

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) wrote :

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) wrote :

/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) wrote :

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) wrote :

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

Changed in squid (Ubuntu):
importance: Medium → High
Andreas Hasenack (ahasenack) wrote :

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

Changed in squid (Ubuntu):
status: In Progress → Triaged
Andreas Hasenack (ahasenack) wrote :

Disabling the pinger also works around the problem:

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

summary: - squid crashed with SIGABRT in xassert()
+ assertion error when rotating logs
Andreas Hasenack (ahasenack) wrote :

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

Changed in squid (Ubuntu):
status: Triaged → In Progress
Launchpad Janitor (janitor) wrote :

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

Changed in squid (Ubuntu):
status: In Progress → Fix Released
Changed in squid (Debian):
status: Unknown → Confirmed
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.