Caddy: Reloading via SIGUSR1 not working when started with exec

[ionphractal]

1. What version of Caddy are you running (caddy -version)?

Caddy 0.9.5 (+ccdc286 Thu Feb 23 15:09:08 UTC 2017)

2. What are you trying to do?

I'm using supervisord to start Caddy inside a container.
Because I have to set some command line parameter dynamically, I'm executing caddy binary inside a bash script.
Caddy needs to be executed with exec for supervisord to be able to control it.
I'm also using consul-template that should reload Caddy when configuration changes and therefore sends a SIGUSR1 to the process.

3. What is your entire Caddyfile?

:80 { 
        log stdout
        errors stderr
        redir https://{host}{uri}
}

:443 {
        log stdout
        errors stderr
        gzip

        tls {
                load /caddy/ssl
        }

        root /caddy/sites.d/0-default
        markdown /
}
{$BACKEND_DOMAIN} {     
        expvar /stats   
        log stdout
        errors stderr   
        gzip

        tls {$DEFAULT_EMAIL}

        basicauth / {$BACKEND_USER} {$BACKEND_PASSWORD}

        proxy / {$BACKEND_URL} {
                policy least_conn
                transparent
                insecure_skip_verify
                fail_timeout 10s
                max_fails 1
                try_duration 1s
        }
}

http://dev.local {
        log stdout
        errors stderr
        gzip 

        proxy / dockerhost.local:32793 {
                policy least_conn
                transparent
                insecure_skip_verify
                fail_timeout 10s
                max_fails 1
                try_duration 1s
        }
}

4. How did you run Caddy (give the full command and describe the execution environment)?

/go/bin/caddy -conf /caddy/Caddyfile -log stdout

5. What did you expect to see?

I would expect Caddy to be reloaded with messages like:

2017/02/23 15:52:13 [INFO] SIGUSR1: Reloading
2017/02/23 15:52:13 [INFO] Reloading
2017/02/23 15:52:13 [INFO] Reloading complete

6. What did you see instead (give full error messages and/or log)?

Reloading does not complete and new configuration is not loaded. Even though Caddy got the event:

2017/02/23 15:52:13 [INFO] SIGUSR1: Reloading
2017/02/23 15:52:13 [INFO] Reloading

It'll never report "Reloading complete".
Another SIGUSR1 sent to the process is completely ignored.
This only happens when I use "-conf" parameter.

7. How can someone who is starting from scratch reproduce this behavior as minimally as possible?

1. Build, e.g. like the following Docker image: docker build -t "caddy/minimal" .
   Dockerfile

FROM golang:1.8-alpine

ENV CADDY_VERSION="0.9.5-x" \
  CADDY_SRC_URL="https://github.com/mholt/caddy.git" \
  CADDY_COMMIT_SHA="ccdc28631aa6f398a24ab70cd6404a84ac1ae0c5" \
  CADDY_BINARY="caddy" \
  CA="https://acme-staging.api.letsencrypt.org/directory" \
  HOME="/caddy"
# Commit #1749 22.02.2017

RUN apk update && apk upgrade \
 && apk add libcap bash supervisor git unzip

RUN cd / \
 && git clone ${CADDY_SRC_URL} /tmp/build \
 && cd /tmp/build/ \
 && git checkout ${CADDY_COMMIT_SHA} \
 && cd ${CADDY_BINARY} \
 && go get -d \
 && bash build.bash \
 && mv ${CADDY_BINARY} ${GOPATH}/bin \
 && setcap cap_net_bind_service=+ep ${GOPATH}/bin/${CADDY_BINARY} \
 && mkdir -p "${HOME}" \
 && chown nobody:nogroup "${HOME}" \
 && rm -rf /var/cache/apk/* \
 && rm -Rf /tmp/build \
 && mkdir -p /caddy/sites.d/0-default /caddy/ssl

1. Start a container:

docker run -it caddy/minimal bash

1. Add above Caddyfile to /caddy
   Create the following script
   start.sh:

#!/bin/bash
exec /go/bin/caddy -conf /caddy/Caddyfile -log stdout

1. Start with:

bash start.sh &

1. Try to reload with:

pkill -SIGUSR1 /go/bin/caddy

[mholt]

Any container gurus want to look into this?

[francislavoie]

So, I think the solution is to use trap in the shell script to capture signals and pass them on. Funny, I was working on this exact issue (but not for Caddy) today!

Quick example:

# forward SIGUSR1 to the process
trap 'kill -USR1 $PID; echo "SIGUSR1"' USR1 INT

# change process state, specifies user
exec /go/bin/caddy -conf /caddy/Caddyfile -log stdout &

# get the PID and wait, see trap above and link below
# http://veithen.github.io/2014/11/16/sigterm-propagation.html
PID=$!
wait $PID
trap - USR1 INT
wait $PID
STATUS=$?

You might need to adapt this, I haven't tested it so no guarantees, but it'd be something to try.

Without more information, I don't think this is really an issue for Caddy but something to be solved via better scripting.

[AndreKR]

How sure are you about this?

and new configuration is not loaded

The reason why you don't see 2017/02/23 15:52:13 [INFO] Reloading complete has nothing to do with containers, bash or exec.

It is simply because during the reload the onShutdown function of the instance is called and that closes the logger. When logging to stdout, that effectively means os.Stdout.Close() which makes further log output to the console impossible.

This is reproducible with a minimal Caddyfile

:80 {
        log stdout
        errors stderr
        redir https://{host}{uri}
}

by starting caddy with ./caddy -conf Caddyfile -log stdout and sending SIGUSR1 to the process from another shell.

However, I don't see how this would interfere with the actual reloading of the Caddyfile.

[mholt]

Ohh, I didn't even see that! Great point, @AndreKR. If there's no response from the OP after a while I'll close this.

[AndreKR]

Closing os.Stdout does seem like a bug to me. :)

[ionphractal]

How sure are you about this?

I'm sure about this because I can observe 502 Bad Gateway after an app container is restarted.
The container gets assigned another port triggering Registrator to update Consul, generating a new config template (using consul-template) and finally reloading Caddy using SIGUSR1.
If I forcefully restart Caddy in that situation, the 502 resolves and everything works again.

@AndreKR Thanks for the explanation though. It explains the log behaviour of "reloading complete". Yet, stdout should be opened again when loading a new configuration? But I don't remember if this was the case for other log messages. I'll double check that (not today though).

I'll try @francislavoie 's suggestion first and if that doesn't work, maybe it would be possible to keep stdout / the logger open? I'd probably need help with that because I don't know Go. Open for any advice.

[mholt]

Okay, looking into this (not closing the streams).

[mholt]

@ionphractal Are you able to build from source and try again? Can you try https://github.com/mholt/caddy/pull/1596 (the closinglogs branch)?

[ionphractal]

@mholt I was just able to test the new commit, works like a charm! Great work, thank you!