Remove some startup logs when running behind load balancer

1. Caddy version (caddy version):

xcaddy build v2.4.6 --with github.com/baldinof/caddy-supervisor --with github.com/leodido/caddy-jsonselect-encoder

2. How I run Caddy:

Caddyfile

a. System environment:

caddy:2.4.6 docker file on Google Cloud Run.

ARG root_image

FROM $root_image

ADD /usr_bin_caddy /usr/bin/caddy
ADD /usr_sbin_php-fpm7 /usr/sbin/php-fpm
RUN chmod +x /usr/bin/caddy /usr/sbin/php-fpm

RUN rm -rf /lib /usr/lib
ADD /lib.tar /
ADD /usr_lib.tar /usr

ADD /etc_php7 /etc/php7
ADD /project /project
run mkdir -p /project/runtime /assets-manifest-cache /config/caddy
WORKDIR /project/tools/runtime_config

run chown 1000 -R /project/runtime /assets-manifest-cache /config
USER 1000

CMD ["/usr/bin/env", "caddy", "run"]

(the context comes from copying from this dockerfile)

ARG caddy_builder
FROM $caddy_builder as caddy

FROM caddy:2.4.6

COPY --from=caddy /usr/bin/caddy /usr/bin/caddy
COPY --from=composer:latest /usr/bin/composer /usr/bin/composer

# https://github.com/nunomaduro/phpinsights/issues/43#issuecomment-917389852
RUN apk --no-cache add php7-mbstring php7-iconv

RUN apk --no-cache add php7-opcache php7-memcached php7-session php7-fpm php7-bcmath php7-phar php7-json php7-openssl php7-simplexml php7-pdo

ADD webserver/composer.json /project/webserver/composer.json
ADD webserver/composer.lock /project/webserver/composer.lock
WORKDIR /project/webserver
RUN composer install --no-dev --optimize-autoloader --no-scripts --no-plugins --prefer-dist --no-interaction

(I get root_image build arg from finding the hash of the caddy:2.4.6 used in the image I use to do the composer install)

b. Command:

caddy run

c. Service/unit/compose file:

N/A

d. My complete Caddyfile or JSON config:

{
	admin off
	auto_https off
	supervisor {
		php-fpm -p . -c . -y fpm.conf -F {
			redirect_stdout stderr
			redirect_stderr stderr
		}
	}

	log {
		format json {
			level_key "severity"
			level_format "upper"
			time_format "rfc3339_nano"
		}
	}
}

:8087 {
	@trailing-slash {
		path_regexp dir (.+)/$
	}
	rewrite @trailing-slash {re.dir.1}

	root * ../../webserver/portal

	try_files {path} {path}.php {path}/index.php =404
	php_fastcgi unix/../../runtime/fpm.sock {
		# php-fpm takes a few seconds the first time
		lb_try_duration 5s
	}

	log {
		output {$CADDY_LOG_OUTPUT}
		format jsonselect "{severity:level} {timestamp:ts} {logName:logger} {httpRequest>requestMethod:request>method} {httpRequest>protocol:request>proto} {httpRequest>status:status} {httpRequest>responseSize:size} {httpRequest>userAgent:request>headers>User-Agent>[0]} {httpRequest>requestUrl:request>uri}" "{httpRequest>referrer:request>headers>Referer>[0]}" {
			level_format "upper"
			time_format "rfc3339_nano"
		}
	}

	encode zstd gzip

	handle_errors {
		@404 {
			expression {http.error.status_code} == 404
		}
		rewrite @404 /not-found.php
		reverse_proxy @404 unix/../../runtime/fpm.sock {
			transport fastcgi {
				split .php
			}
		}
	}
}

3. The problem Iā€™m having:

I have auto_https set to off because Iā€™m letting the google load balancer manage tls but I still get the following logs when I start caddy. Are there further options thatā€™ll make less of them happen?

and when it shuts down

For some reason chown 1000 /config/caddy in the docker file does nothing despite working on other directories (and I see in another post that the persist option isnā€™t exposed to the Caddyfile), and Iā€™d expect it not talk about certificate maintenance or storage.

Also, I use caddy fmt -overwrite and it doesnā€™t change the Caddyfile, which is 70 lines long, so I assume itā€™s complaining about a missing newline or something?

I assume the uncaught signal is related to supervise, but Iā€™m unsure where itā€™s coming from so it quite possibly could be unrelated to caddy and php-fpm

You used a lowercase run here instead of RUN. Iā€™m not sure if that makes a difference :thinking:

Anyways, the base caddy docker image defines a VOLUME /config, you should definitely make volumes for this and /data to persist the data.

I donā€™t know much about ā€œGoogle Cloud Runā€ so the permissions issue for the autosave.json is probably something platform-specific, I canā€™t answer that specifically.

Are you talking about the "logger": "tls" lines? Thatā€™s normal, the HTTP app always loads the TLS app which triggers those maintenance messages. Theyā€™re harmless, Caddy isnā€™t actually doing anything other than starting a routine in case itā€™s needed.

As for the caddy fmt warning, it seems to complain about an issue on line 71, but thereā€™s only 55 lines in the Caddyfile you posted. Are you sure youā€™re running the config you think you are? Canā€™t really answer the reason unless you actually post the config youā€™re running.

Either way, the caddy fmt warning is just a warning, itā€™s a suggestion to take action, but you can ignore it if you donā€™t care (or canā€™t figure out the problem).

caddy docker image defines a VOLUME /config

ahh, thatā€™s why the chown does nothing. Can I change where the autosave saves to?

Theyā€™re harmless

Yeah, the logs are all harmless. Itā€™s just noisy because google run is by design making the workers come up and down as needed. Iā€™ll ignore them if I canā€™t remove them, but itā€™d be nice to have less noise :slight_smile:

but thereā€™s only 55 lines in the Caddyfile you posted

Sorry, I forgot to mention I deleted some business logic redirects from what I post. The actual Caddyfile is 70 lines long.

You canā€™t change the filename, but you can change the ā€œconfig storage locationā€ via the XDG_CONFIG_HOME env var. The base Docker image sets it to /config already though, no reason to change it. See Conventions ā€” Caddy Documentation

The autosave is really there for the config API usecase of Caddy, where you used the API to manipulate the config inhmemory ā€“ saves it to file so if you restart Caddy you donā€™t lose any config changes and can use --resume to load from the autosave. But if you use a Caddyfile, then itā€™s not useful for you.

Please post your unredacted config. I canā€™t really suggest anything on the fmt point otherwise.

Your post gave the idea that we could have a caddy fmt --diff mode which would show which lines differ. I wrote that up real quick here:

1 Like

You canā€™t change the filename, but you can change the ā€œconfig storage locationā€ via the XDG_CONFIG_HOME env va

Awesome, Iā€™ll give that a shot

Please post your unredacted config.

If I remove the redirects locally so my caddyfile is the same, the error becomes:

2022/04/11 06:16:44.002 WARN input is not formatted with 'caddy fmt' {"adapter": "caddyfile", "file": "Caddyfile", "line": 56}

Your post gave the idea that we could have a caddy fmt --diff mode

ooh, great idea.

I ran it and it doesnā€™t seem to complain gist:67f0f23ddb9eccd98c8bbd7c7e47f68a Ā· GitHub

And it looks correct to me when I make the tabs visible

Iā€™m unsure how to build a local caddy with the two modules I use though so I canā€™t run it with that caddy binary without removing supervise and the jsonformat stuff, and if I do that it no longer complains about the formatting

oh, I think I know what it is. The jsonformat line is too long. Can I split that across multiple lines?

I donā€™t think line length matters.

It might be the missing trailing newline?

You canā€™t change the filename, but you can change the ā€œconfig storage locationā€ via the XDG_CONFIG_HOME env var

Awesome, Iā€™ll give that a shot

Yay, it worked :slight_smile:

I donā€™t think line length matters.

Actually youā€™re right, If I make that section

	log {
		output {$CADDY_LOG_OUTPUT}
		format jsonselect "{severity:level}" {
			level_format "upper"
			time_format "rfc3339_nano"
		}
	}

Then it still complains.

It stops complaining when I remove

		output {$CADDY_LOG_OUTPUT}

(in dev thatā€™s set to stderr, in cloud run itā€™s set to discard, because cloud run logs request logs and caddy was just repeating it)

Thatā€™s strange. Is there a newline or something in the env var value? The formatter should be running before the env var is replaced though, so Iā€™m confused. I canā€™t replicate an issue with just that line :thinking:

I have a test you can replicate with here GitHub - delfick/caddy-test: https://caddy.community/t/remove-some-startup-logs-when-running-behind-load-balancer/15617/10

$ CADDY_LOG_OUTPUT="stderr" ./caddy validate --config Caddyfile.test
2022/04/11 07:18:12.933 INFO    using provided configuration    {"config_file": "Caddyfile.test", "config_adapter": ""}
2022/04/11 07:18:12.934 WARN    input is not formatted with 'caddy fmt' {"adapter": "caddyfile", "file": "Caddyfile.test", "line": 19}
2022/04/11 07:18:12.935 INFO    tls.cache.maintenance   started background certificate maintenance      {"cache": "0xc00048bab0"}
2022/04/11 07:18:12.935 INFO    tls.cache.maintenance   stopped background certificate maintenance      {"cache": "0xc00048bab0"}
Valid configuration


$ CADDY_LOG_OUTPUT="discard" ./caddy validate --config Caddyfile.test
2022/04/11 07:18:28.143 INFO    using provided configuration    {"config_file": "Caddyfile.test", "config_adapter": ""}
2022/04/11 07:18:28.148 INFO    tls.cache.maintenance   started background certificate maintenance      {"cache": "0xc000225260"}
2022/04/11 07:18:28.148 INFO    tls.cache.maintenance   stopped background certificate maintenance      {"cache": "0xc000225260"}
Valid configuration

WAT?

Why does it warn with stderr but not with discard???

:scream:

Wow ok, so building with v2.5.0-beta.1, there doesnā€™t seem to be a formatting issue. So try that I guess.

:scream:

hehehhe

It seems to also complain with discard if I add the handle_error also fails with the handle_errors if we have discard Ā· delfick/caddy-test@4166717 Ā· GitHub

Oh. Right, itā€™s this fix:

I totally forgot that went in. So yeah, fmt with env vars had a bug I guess.

1 Like

with my current Caddyfile 2.5.0-beta.1 doesnā€™t complain about formatting. So thatā€™ll go away when you release 2.5.0 itself and I can use it :slight_smile:

This is better

I changed my Caddyfile to have this in the global options

	log {
		format json {
			time_key "time"
			level_key "severity"
			message_key "message"
			level_format "upper"
			time_format "rfc3339_nano"
		}
	}

so stackdriver sees them better. Seems that first one happens before itā€™s read though.

The fmt messages goes away when I can use 2.5.0

Having the ā€œnot using adminā€ as an info instead of warning would be nice, but oh well.

For shut down, itā€™d be cool if the exiting message was info instead of warning. And Iā€™m still figuring out how to make it so php-fpm is gone before cloud run thinks the caddy process is finished (cause caddy finishes before php-fpm does) and then thatā€™ll remove the error log

Screen Shot 2022-04-11 at 5.56.37 pm

1 Like

You can use it now, honestly. Itā€™s pretty stable. One known issue with caddy reload (fixed on master), but otherwise you can use the beta. If you need reload, build from commit cmd: Fix defaulting admin address if empty in config, fixes `reload` ā€¦ Ā· caddyserver/caddy@22d8edb Ā· GitHub which has the fix.

Probably need to open an issue on the caddy-supervisor plugin to add a thing to wait on the command to finish before letting Caddy turn off

1 Like

You can use it now, honestly. Itā€™s pretty stable

I believe you, itā€™s more convincing others thatā€™s the problem, easier just to wait.

Probably need to open an issue on the caddy-supervisor plugin to add a thing to wait on the command to finish before letting Caddy turn off

Looks like I found the problem - shutdown: can't call Wait twice by delfick Ā· Pull Request #5 Ā· Baldinof/caddy-supervisor Ā· GitHub

In the meantime Iā€™m gonna run caddy in this wrapper

#!/bin/sh

set -e

${CADDY:-/usr/bin/caddy} run &
trap "kill -TERM $! && wait && while pgrep php-fpm >/dev/null; do sleep 0.5; done" TERM INT
wait

I donā€™t get to put any of this in prod for a while, so hopefully the PR gets a response/edit/merge before then :slight_smile:

1 Like

This topic was automatically closed after 30 days. New replies are no longer allowed.