Varnish and Varnish-Agent start order

[mariusmagureanu]

When starting the Agent it is required that Varnish is already running, otherwise syslog gets filled with logs like the ones below:

Apr 5 12:39:36 var02 varnishd[1795]: Platform: Linux,4.4.0-70-generic,x86_64,-junix,-smse,-smalloc,-hcritbit 
Apr 5 12:39:36 var02 varnish-agent[1814]: http_run (modules/http.c:445): HTTP starting on port 6085 
Apr 5 12:39:36 var02 varnish-agent[1814]: send_curl (modules/vac_register.c:80): Sending VAC registration request: http://vac:8080/api/rest/register?hostname=var02 
Apr 5 12:39:36 var02 varnish-agent[1814]: issue_curl (modules/curl.c:108): Issuing curl command with url=http://vac:8080/api/rest/register?hostname=var02. Request body present 
Apr 5 12:39:36 var02 varnishd[1795]: Child (1822) Started 
Apr 5 12:39:36 var02 varnish-agent[1814]: log_request (modules/http.c:311): GET /ping 
Apr 5 12:39:36 var02 varnish-agent[1814]: n_arg_sock (modules/vadmin.c:102): Couldn't open VSM: Cannot open /var/lib/varnish/var02/_.vsm: No such file or directory 
Apr 5 12:39:36 var02 varnish-agent[1814]: n_arg_sock (modules/vadmin.c:113): No -T arg and no shmlog readable. 
Apr 5 12:39:36 var02 varnish-agent[1814]: cli_sock (modules/vadmin.c:162): No T-arg (Administration port) available. Varnishadm-commands wont work. 
Apr 5 12:39:36 var02 varnish-agent[1814]: log_request (modules/http.c:311): GET /ping 
Apr 5 12:39:36 var02 varnish-agent[1814]: n_arg_sock (modules/vadmin.c:102): Couldn't open VSM: Cannot open /var/lib/varnish/var02/_.vsm: No such file or directory 
Apr 5 12:39:36 var02 varnish-agent[1814]: n_arg_sock (modules/vadmin.c:113): No -T arg and no shmlog readable. 
Apr 5 12:39:36 var02 varnish-agent[1814]: cli_sock (modules/vadmin.c:162): No T-arg (Administration port) available. Varnishadm-commands wont work. 
Apr 5 12:39:36 var02 varnishd[1795]: Child (1822) said Child starts 
Apr 5 12:39:36 var02 varnishd[1795]: Child (1822) said MSE: (s0_0) 0 bytes of journal processed 
Apr 5 12:39:36 var02 varnishd[1795]: Child (1822) said MSE: (s0_0) Populator thread finished (revived=0 dropped=0 cleaned=0) 
Apr 5 12:39:36 var02 varnishd[1795]: Child (1822) said MSE: (s0_1) 0 bytes of journal processed 
Apr 5 12:39:36 var02 varnishd[1795]: Child (1822) said MSE: (s0) Persistent stevedore ready for traffic 
Apr 5 12:39:36 var02 varnishd[1795]: Child (1822) said MSE: (s0_1) Populator thread finished (revived=0 dropped=0 cleaned=0) 
Apr 5 12:39:37 var02 varnish-agent[1814]: log_request (modules/http.c:311): GET /stats 
Apr 5 12:39:37 var02 varnish-agent[1814]: log_request (modules/http.c:311): GET /backendjson/ 
Apr 5 12:39:37 var02 varnish-agent[1814]: n_arg_sock (modules/vadmin.c:144): -T argument computed to: 127.0.0.1 6082 
Apr 5 12:39:37 var02 varnish-agent[1814]: cli_sock (modules/vadmin.c:186): Cannot open "/etc/varnish/secret": Permission denied 
Apr 5 12:39:37 var02 varnish-agent[1814]: log_request (modules/http.c:311): GET /backendjson/ 
Apr 5 12:39:37 var02 varnish-agent[1814]: n_arg_sock (modules/vadmin.c:144): -T argument computed to: 127.0.0.1 6082 
Apr 5 12:39:37 var02 varnish-agent[1814]: cli_sock (modules/vadmin.c:186): Cannot open "/etc/varnish/secret": Permission denied 
Apr 5 12:39:37 var02 varnish-agent[1814]: log_request (modules/http.c:311): GET /stats 
Apr 5 12:39:37 var02 varnish-agent[1814]: log_request (modules/http.c:311): GET /ping 
Apr 5 12:39:37 var02 varnish-agent[1814]: n_arg_sock (modules/vadmin.c:144): -T argument computed to: 127.0.0.1 6082 
Apr 5 12:39:37 var02 varnish-agent[1814]: cli_sock (modules/vadmin.c:186): Cannot open "/etc/varnish/secret": Permission denied 
Apr 5 12:39:37 var02 varnish-agent[1814]: log_request (modules/http.c:311): GET /ping 

This issue is a follow-up of the 14367 ticket.

[dridi]

It looks like we should improve the sysv/systemd services to account for this dependency. And also take advantage of the shmlog timeout for versions where it is supported (I think 4.1+).

[freshteapot]

@dridi What do you mean shmlog timeout? I did a quick google and it was not clear.

[dridi]

See the -t flag on tools like varnishlog or varnishncsa:

http://varnish.org/docs/4.1/reference/varnishlog.html

Between the moment where your service manager starts Varnish (even before the agent, assuming correct dependencies) it can take time until Varnish is actually ready. For example it might take time to allocate dozens of gigs on disk for a file-based storage. So even if varnish is started, it may not be ready so it may take noticeable time until the agent gets a hold on the SHared Memory LOG (shmlog).

[dridi]

@carlosabalde, you may want to subscribe to this issue.

[carlosabalde]

Thanks. Already subscribed :)

[freshteapot]

@dridi thanks, in my head, I read this that the agent would watch the shmlog until it saw that varnish was online.

[dridi]

@freshteapot it depends on how ready you expect Varnish to be. We have a solution for this in Varnish that I would like to discuss further with @denisbr before I do anything in utilities like the agent.

[dridi]

The -t option being already supported, all that is left is ensuring that /etc/varnish/secret is owned by root:varnish with permissions 640 to ensure that 1) start order works fine and 2) we can contact varnishd again when it restarts (and we already dropped root privileges to varnish:varnish).

Since we are dropping the secret file from varnish packaging, this is now a non-issue.