Bug 1371181 - varnishlog and varnishncsa fail to start
Summary: varnishlog and varnishncsa fail to start
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: varnish
Version: 23
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: ---
Assignee: Ingvar Hagelund
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-08-29 14:05 UTC by Chad
Modified: 2016-09-23 03:22 UTC (History)
1 user (show)

Fixed In Version: varnish-4.1.3-5.fc25 varnish-4.1.3-5.fc24 varnish-4.1.3-5.fc23
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-09-06 18:21:48 UTC


Attachments (Terms of Use)

Description Chad 2016-08-29 14:05:01 UTC
Description of problem:
Both the varnishlog and varnishncsa services fail to start

Version-Release number of selected component (if applicable):
varnish-4.1.3-3.fc23.x86_64
varnish-libs-4.1.3-3.fc23.x86_64

How reproducible:
Try to start the vanishlog or varnishncsa services via systemctl

Steps to Reproduce:
1. systemctl start varnishlog
2. systemctl start varnishncsa

Actual results:
$ systemctl start varnishlog
Job for varnishlog.service failed because the control process exited with error code. See "systemctl status varnishlog.service" and "journalctl -xe" for details.

$ systemctl status varnishlog -l
● varnishlog.service - Varnish Cache HTTP accelerator logging daemon
   Loaded: loaded (/usr/lib/systemd/system/varnishlog.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Mon 2016-08-29 08:59:13 CDT; 6s ago
  Process: 12977 ExecStart=/usr/bin/varnishlog -a -w /var/log/varnish/varnish.log -D -P /run/varnishlog/varnishlog.pid (code=exited, status=217/USER)

Aug 29 08:59:13 <snip> systemd[1]: Starting Varnish Cache HTTP accelerator logging daemon...
Aug 29 08:59:13 <snip> systemd[1]: varnishlog.service: Control process exited, code=exited status=217
Aug 29 08:59:13 <snip> systemd[1]: Failed to start Varnish Cache HTTP accelerator logging daemon.
Aug 29 08:59:13 <snip> systemd[1]: varnishlog.service: Unit entered failed state.
Aug 29 08:59:13 <snip> systemd[1]: varnishlog.service: Failed with result 'exit-code'.


Expected results:


Additional info:

$ cat /usr/lib/systemd/system/varnishlog.service 
[Unit]
Description=Varnish Cache HTTP accelerator logging daemon
After=varnish.service

[Service]
RuntimeDirectory=varnishlog
Type=forking
PIDFile=/run/varnishlog/varnishlog.pid
User=varnishlog
Group=varnish
ExecStart=/usr/bin/varnishlog -a -w /var/log/varnish/varnish.log -D -P /run/varnishlog/varnishlog.pid
ExecReload=/bin/kill -HUP $MAINPID

[Install]
WantedBy=multi-user.target


$ id varnishlog
id: varnishlog: no such user

$ ls -ld /run/varnishlog
ls: cannot access /run/varnishlog: No such file or directory

Comment 1 Fedora Update System 2016-08-30 03:49:22 UTC
varnish-4.1.3-4.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2016-2da04e634f

Comment 2 Fedora Update System 2016-08-30 03:49:28 UTC
varnish-4.1.3-4.fc23 has been submitted as an update to Fedora 23. https://bodhi.fedoraproject.org/updates/FEDORA-2016-c04817d62b

Comment 3 Fedora Update System 2016-08-30 03:49:32 UTC
varnish-4.1.3-4.fc24 has been submitted as an update to Fedora 24. https://bodhi.fedoraproject.org/updates/FEDORA-2016-9a51c6b278

Comment 4 Fedora Update System 2016-08-31 03:52:21 UTC
varnish-4.1.3-4.fc25 has been pushed to the Fedora 25 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-2da04e634f

Comment 5 Fedora Update System 2016-08-31 12:57:25 UTC
varnish-4.1.3-4.fc23 has been pushed to the Fedora 23 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-c04817d62b

Comment 6 Fedora Update System 2016-08-31 12:57:34 UTC
varnish-4.1.3-4.fc24 has been pushed to the Fedora 24 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-9a51c6b278

Comment 7 Chad 2016-08-31 16:04:13 UTC
Updated to 4.1.3-4 (fc23); vanishlog and varnishnsca still fail to start.

$ cat /usr/lib/systemd/system/varnishlog.service 
[Unit]
Description=Varnish Cache HTTP accelerator logging daemon
After=varnish.service

[Service]
RuntimeDirectory=varnishlog
Type=forking
PIDFile=/run/varnishlog/varnishlog.pid
User=varnish
Group=varnish
ExecStart=/usr/bin/varnishlog -a -w /var/log/varnish/varnish.log -D -P /run/varnishlog/varnishlog.pid
ExecReload=/bin/kill -HUP $MAINPID

[Install]
WantedBy=multi-user.target


Notice, the service is still expecting the PIDFile to exist in /run/varnishlog.  That directory does not exist.

1) The PIDFile location needs to be changed to /run/varnishlog.pid

OR

2) The package should install a tmpfiles.d configuration file which creates the /run/varnishlog directory with the appropriate permissions (preferred)

Comment 8 Ingvar Hagelund 2016-08-31 21:10:02 UTC
This is strange, as this should work without any tmpfiles.d configuration, as it uses the RuntimeDirectory statement in the systemd service file. This is straight out of the manpage systemd.exec(5).

I tested the package today (the update from updates-testing), on both f23 and f24. It seems to work fine. varnishlog and varnishncsa starts fine. (Note that varnishd have to run for this to work.

Can you verify that you

1) actually have tested the version in updates-testing
2) don't have any extra variants of the varnish*.service files in /etc/systemd/system
3) test this on fedora, and not, for instance on epel7

Ingvar

Comment 9 Chad 2016-09-01 13:30:42 UTC
Tested on 3 separate, Fedora 23 servers.

$ rpm -qi varnish
Name        : varnish
Version     : 4.1.3
Release     : 4.fc23
Architecture: x86_64
Install Date: Wed 31 Aug 2016 10:57:37 AM CDT
Group       : System Environment/Daemons
Size        : 1210701
License     : BSD
Signature   : (none)
Source RPM  : varnish-4.1.3-4.fc23.src.rpm
Build Date  : Mon 29 Aug 2016 05:23:55 PM CDT
Build Host  : buildvm-13.phx2.fedoraproject.org
Relocations : (not relocatable)
Packager    : Fedora Project
Vendor      : Fedora Project
URL         : http://www.varnish-cache.org/
Summary     : High-performance HTTP accelerator
Description :
This is Varnish Cache, a high-performance HTTP accelerator.

Varnish Cache stores web pages in memory so web servers don't have to
create the same web page over and over again. Varnish Cache serves
pages much faster than any application server; giving the website a
significant speed up.

Documentation wiki and additional information about Varnish Cache is
available on the following web site: https://www.varnish-cache.org/

$ ls -l /etc/systemd/system/varnish*
ls: cannot access /etc/systemd/system/varnish*: No such file or directory

$ cat /etc/os-release 
NAME=Fedora
VERSION="23 (Twenty Three)"
ID=fedora
VERSION_ID=23
PRETTY_NAME="Fedora 23 (Twenty Three)"
ANSI_COLOR="0;34"
CPE_NAME="cpe:/o:fedoraproject:fedora:23"
HOME_URL="https://fedoraproject.org/"
BUG_REPORT_URL="https://bugzilla.redhat.com/"
REDHAT_BUGZILLA_PRODUCT="Fedora"
REDHAT_BUGZILLA_PRODUCT_VERSION=23
REDHAT_SUPPORT_PRODUCT="Fedora"
REDHAT_SUPPORT_PRODUCT_VERSION=23
PRIVACY_POLICY_URL=https://fedoraproject.org/wiki/Legal:PrivacyPolicy

Updated varnish on a 4th server.  Current varnshlog process was still running.  Performed a restart and it failed.


# systemctl status varnishlog -l
● varnishlog.service - Varnish Cache HTTP accelerator logging daemon
   Loaded: loaded (/usr/lib/systemd/system/varnishlog.service; enabled; vendor preset: disabled)
   Active: active (running) since Thu 2016-08-18 07:48:13 CDT; 2 weeks 0 days ago
 Main PID: 28127 (varnishlog)
   CGroup: /system.slice/varnishlog.service
           └─28127 /usr/bin/varnishlog -a -w /var/log/varnish/varnish.log -D -P /run/varnishlog.pid

Aug 18 07:48:13 <snip> systemd[1]: Starting Varnish Cache HTTP accelerator logging daemon...
Aug 18 07:48:13 <snip> systemd[1]: Started Varnish Cache HTTP accelerator logging daemon.
# 
# systemctl restart varnishlog
Job for varnishlog.service failed because the control process exited with error code. See "systemctl status varnishlog.service" and "journalctl -xe" for details.
# 
# systemctl status varnishlog -l
● varnishlog.service - Varnish Cache HTTP accelerator logging daemon
   Loaded: loaded (/usr/lib/systemd/system/varnishlog.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Thu 2016-09-01 08:17:01 CDT; 2s ago
  Process: 1672 ExecStart=/usr/bin/varnishlog -a -w /var/log/varnish/varnish.log -D -P /run/varnishlog/varnishlog.pid (code=exited, status=2)
 Main PID: 28127 (code=exited, status=0/SUCCESS)

Sep 01 08:17:01 <snip> systemd[1]: Starting Varnish Cache HTTP accelerator logging daemon...
Sep 01 08:17:01 <snip> systemd[1]: varnishlog.service: Control process exited, code=exited status=2
Sep 01 08:17:01 <snip> systemd[1]: Failed to start Varnish Cache HTTP accelerator logging daemon.
Sep 01 08:17:01 <snip> systemd[1]: varnishlog.service: Unit entered failed state.
Sep 01 08:17:01 <snip> systemd[1]: varnishlog.service: Failed with result 'exit-code'.


The short of it all is that it's not the runtime directory or pidfile; it's permissions on the logfiles.

varnishlog:

Sep  1 08:22:08 clip systemd: Starting Varnish Cache HTTP accelerator logging daemon...
Sep  1 08:22:08 clip varnishlog: Can't open output file (Permission denied)
Sep  1 08:22:08 clip systemd: varnishlog.service: Control process exited, code=exited status=2
Sep  1 08:22:08 clip systemd: Failed to start Varnish Cache HTTP accelerator logging daemon.
Sep  1 08:22:08 clip systemd: varnishlog.service: Unit entered failed state.
Sep  1 08:22:08 clip audit: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=varnishlog comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Sep  1 08:22:08 clip systemd: varnishlog.service: Failed with result 'exit-code'.

varnishncsa:

Sep  1 08:24:31 clip systemd: Starting Varnish Cache HTTP accelerator NCSA logging daemon...
Sep  1 08:24:31 clip varnishncsa: Can't open output file (Permission denied)
Sep  1 08:24:31 clip systemd: varnishncsa.service: Control process exited, code=exited status=1
Sep  1 08:24:31 clip systemd: Failed to start Varnish Cache HTTP accelerator NCSA logging daemon.
Sep  1 08:24:31 clip audit: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=varnishncsa comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Sep  1 08:24:31 clip systemd: varnishncsa.service: Unit entered failed state.
Sep  1 08:24:31 clip systemd: varnishncsa.service: Failed with result 'exit-code'.

$ ls -l /var/log/varnish/varnish*.log
-rw-r--r--. 1 root root 4 Sep  1 03:47 /var/log/varnish/varnish.log
-rw-r--r--. 1 root root 0 Sep  1 03:47 /var/log/varnish/varnishncsa.log

$ rm -f /var/log/varnish/varnish*.log
$ systemctl restart varnishlog
$ systemctl restart varnishnsca

Success.

The logfiles of old, created from the previous varnish package, had permissions of root:root.  Now they are expected to be varnish:varnish.  This prevents a restart of existing varnishlog and varnishncsa services.

Comment 10 Ingvar Hagelund 2016-09-01 21:57:49 UTC
Yep, ownership of the logfiles is the culprit.

Comment 11 Fedora Update System 2016-09-01 22:00:40 UTC
varnish-4.1.3-5.fc24 has been submitted as an update to Fedora 24. https://bodhi.fedoraproject.org/updates/FEDORA-2016-93849b0a4d

Comment 12 Fedora Update System 2016-09-01 22:00:46 UTC
varnish-4.1.3-5.fc23 has been submitted as an update to Fedora 23. https://bodhi.fedoraproject.org/updates/FEDORA-2016-914b30faff

Comment 13 Fedora Update System 2016-09-01 22:00:50 UTC
varnish-4.1.3-5.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2016-a91f6b678d

Comment 14 Fedora Update System 2016-09-03 03:23:37 UTC
varnish-4.1.3-5.fc24 has been pushed to the Fedora 24 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-93849b0a4d

Comment 15 Fedora Update System 2016-09-03 03:53:09 UTC
varnish-4.1.3-5.fc23 has been pushed to the Fedora 23 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-914b30faff

Comment 16 Fedora Update System 2016-09-03 03:54:02 UTC
varnish-4.1.3-5.fc25 has been pushed to the Fedora 25 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-a91f6b678d

Comment 17 Fedora Update System 2016-09-06 18:21:45 UTC
varnish-4.1.3-5.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.

Comment 18 Chad 2016-09-12 13:01:00 UTC
Verified

Comment 19 Fedora Update System 2016-09-23 00:24:42 UTC
varnish-4.1.3-5.fc24 has been pushed to the Fedora 24 stable repository. If problems still persist, please make note of it in this bug report.

Comment 20 Fedora Update System 2016-09-23 03:22:20 UTC
varnish-4.1.3-5.fc23 has been pushed to the Fedora 23 stable repository. If problems still persist, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.