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.