Bug 1478278

Summary: Error messages about invalid argument during start.
Product: [Fedora] Fedora EPEL Reporter: Frank Büttner <bugzilla>
Component: varnishAssignee: Ingvar Hagelund <ingvar>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: epel7CC: ingvar
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: varnish-4.0.5-3.el7 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2022-03-03 15:23:40 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Frank Büttner 2017-08-04 07:51:03 UTC
Description of problem:
When start the 3 services (varnish,varnishlog and varnishncsa) an error message will be reported.

Version-Release number of selected component (if applicable):
varnish-4.0.4-3.el7.x86_64

How reproducible:
Every time

Steps to Reproduce:
1. yum install varnish
2. systemctl start varnish
3. systemctl start varnishncsa
4. systemctl start varnishlog

Actual results:
Error's in the service status
systemctl status varnish
● varnish.service - Varnish Cache, a high-performance HTTP accelerator
   Loaded: loaded (/usr/lib/systemd/system/varnish.service; disabled; vendor preset: disabled)
   Active: active (running) since Fr 2017-08-04 09:03:12 CEST; 45min ago
  Process: 1348 ExecStart=/usr/sbin/varnishd -P /var/run/varnish.pid -f $VARNISH_VCL_CONF -a ${VARNISH_LISTEN_ADDRESS}:${VARNISH_LISTEN_PORT} -T ${VARNISH_ADMIN_LISTEN_ADDRESS}:${VARNISH_ADMIN_LISTEN_PORT} -S $VARNISH_SECRET_FILE -s $VARNISH_STORAGE $DAEMON_OPTS (code=exited, status=0/SUCCESS)
 Main PID: 1358 (varnishd)
   CGroup: /system.slice/varnish.service
           ├─1358 /usr/sbin/varnishd -P /var/run/varnish.pid -f /etc/varnish/default.vcl -a :6081 -T 127.0.0.1:6082 -S /etc/varnish/secret -s malloc,256M
           └─1359 /usr/sbin/varnishd -P /var/run/varnish.pid -f /etc/varnish/default.vcl -a :6081 -T 127.0.0.1:6082 -S /etc/varnish/secret -s malloc,256M

Aug 04 09:03:12 localhost.localdomain systemd[1]: Starting Varnish Cache, a high-performance HTTP accelerator...
Aug 04 09:03:12 localhost.localdomain systemd[1]: Failed to read PID from file /var/run/varnish.pid: Invalid argument
Aug 04 09:03:12 localhost.localdomain varnishd[1358]: Platform: Linux,3.10.0-514.26.2.el7.x86_64,x86_64,-smalloc,-smalloc,-hcritbit
Aug 04 09:03:12 localhost.localdomain systemd[1]: Started Varnish Cache, a high-performance HTTP accelerator.
Aug 04 09:03:12 localhost.localdomain varnishd[1358]: child (1359) Started
Aug 04 09:03:12 localhost.localdomain varnishd[1358]: Child (1359) said Child starts

Aug 04 09:03:12 localhost.localdomain systemd[1]: Failed to read PID from file /var/run/varnish.pid: Invalid argument



systemctl status varnishlog
● varnishlog.service - Varnish Cache HTTP accelerator logging daemon
   Loaded: loaded (/usr/lib/systemd/system/varnishlog.service; disabled; vendor preset: disabled)
   Active: active (running) since Fr 2017-08-04 09:03:15 CEST; 46min ago
  Process: 1582 ExecStart=/usr/bin/varnishlog -a -w /var/log/varnish/varnish.log -D -P /run/varnishlog/varnishlog.pid (code=exited, status=0/SUCCESS)
 Main PID: 1583 (varnishlog)
   CGroup: /system.slice/varnishlog.service
           └─1583 /usr/bin/varnishlog -a -w /var/log/varnish/varnish.log -D -P /run/varnishlog/varnishlog.pid

Aug 04 09:03:15 localhost.localdomain systemd[1]: Starting Varnish Cache HTTP accelerator logging daemon...
Aug 04 09:03:15 localhost.localdomain systemd[1]: Failed to read PID from file /run/varnishlog/varnishlog.pid: Invalid argument
Aug 04 09:03:15 localhost.localdomain systemd[1]: Started Varnish Cache HTTP accelerator logging daemon.

Aug 04 09:03:15 localhost.localdomain systemd[1]: Failed to read PID from file /run/varnishlog/varnishlog.pid: Invalid argument


systemctl status varnishncsa
● varnishncsa.service - Varnish Cache HTTP accelerator NCSA logging daemon
   Loaded: loaded (/usr/lib/systemd/system/varnishncsa.service; disabled; vendor preset: disabled)
   Active: active (running) since Fr 2017-08-04 09:03:18 CEST; 46min ago
  Process: 1590 ExecStart=/usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -P /run/varnishncsa/varnishncsa.pid (code=exited, status=0/SUCCESS)
 Main PID: 1591 (varnishncsa)
   CGroup: /system.slice/varnishncsa.service
           └─1591 /usr/bin/varnishncsa -a -w /var/log/varnish/varnishncsa.log -D -P /run/varnishncsa/varnishncsa.pid

Aug 04 09:03:18 localhost.localdomain systemd[1]: Starting Varnish Cache HTTP accelerator NCSA logging daemon...
Aug 04 09:03:18 localhost.localdomain systemd[1]: Failed to read PID from file /run/varnishncsa/varnishncsa.pid: Invalid argument
Aug 04 09:03:18 localhost.localdomain systemd[1]: Started Varnish Cache HTTP accelerator NCSA logging daemon.

Aug 04 09:03:18 localhost.localdomain systemd[1]: Failed to read PID from file /run/varnishncsa/varnishncsa.pid: Invalid argument



Expected results:
No errors about Invalid argument.

Comment 1 Ingvar Hagelund 2017-08-04 08:56:07 UTC
This is a simple race between the varnish daemons and systemd. systemd is not patient enough waiting for the daemon to open its pidfile, and gives up.

Workaround: Add 

ExecStartPost=/bin/sleep 0.5

to the varnish*.service files and it should work.


I'll try to figure out how to deal with this most correctly.

Ingvar

Comment 2 Ingvar Hagelund 2017-08-04 09:47:16 UTC
Reproduced with newer versions of varnish (5.1.3) on epel7.

Seems this is not a problem with newer versions of systemd. Fedora 25 and 26 does not have this problem.

So this means that this is a problem with systemd, not with varnish. I'll leave it with the workaround, and add that to the next update of varnish for epel7.

Ingvar

Comment 3 Frank Büttner 2017-08-07 04:44:00 UTC
Hi Ingvar,
I have try it, and it will solve it.

Comment 4 Fedora Update System 2022-02-22 07:58:59 UTC
FEDORA-EPEL-2022-18ac3af1c8 has been submitted as an update to Fedora EPEL 7. https://bodhi.fedoraproject.org/updates/FEDORA-EPEL-2022-18ac3af1c8

Comment 5 Fedora Update System 2022-02-23 16:16:38 UTC
FEDORA-EPEL-2022-18ac3af1c8 has been pushed to the Fedora EPEL 7 testing repository.

You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-EPEL-2022-18ac3af1c8

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

Comment 6 Fedora Update System 2022-03-03 15:23:40 UTC
FEDORA-EPEL-2022-18ac3af1c8 has been pushed to the Fedora EPEL 7 stable repository.
If problem still persists, please make note of it in this bug report.