V2 common log format not working?

Using beta 20 of Caddy v2.

The v2 Upgrade docs say you can get the old common log format like this:

log {
	output file         access.log
	format single_field common_log
}

see: Upgrading to Caddy 2 — Caddy Documentation

Running in development, I can’t seem to get this to work. The “access.log” file isn’t being touched and my screen is still filled with JSON. Is something else needed?

No, nothing else should be required, except to put that directive inside a site definition in your Caddyfile.

Feel free to fill out the full Help category template if you’d like the community here to take a look at your setup and try figure out what your problem might be.

1 Like

Here’s my Caddyfile:

http://localhost, http://192.168.0.95 {
    log {
    	output file         access.log
    	format single_field common_log
    }
    encode gzip

    handle /api/* {
        reverse_proxy localhost:8223
    }
    handle /api/v1/ws/* {
        reverse_proxy localhost:8223
    }

    handle {
        root * ../frontend/dist
        try_files {path} /index.html
        file_server
    }
}

http://localhost:2016, http://192.168.0.95:2016 {
    log {
    	output file         access_ctrl.log
    	format single_field common_log
    }
    encode gzip

    handle /spi/* {
        reverse_proxy localhost:8224
    }
    handle /spi/ws/* {
        reverse_proxy localhost:8224
    }

    handle {
        root * ../ctrl/dist
        try_files {path} /index.html
        file_server
    }
}

Thanks for providing the config!

Hmm, it works for me. I just tested it verbatim.

Make sure you have permission to write to the current working directory?

Also, the default log writes to stderr unless configured otherwise. So you’ll still see access logs there since all logs write from all loggers by default.

I have perms. This was working perfectly under caddy v1. I’ve been updating the Caddyfile to work with v2 and this seems to be the only sticking point.

Also, the default log writes to stderr unless configured otherwise. So you’ll still see access logs there since all logs write from all loggers by default.

I don’t understand. It’s writing INFO and ERROR msgs to the same place (my terminal). Nothing at all is going to the file. What do I have to do to get it to all go to the file, and in the old common log format?

To get all logs to go to a file, you can use the JSON: JSON Config Structure - Caddy Documentation

Set the writer for the sink and the log called “default”. The docs on that page should be informative here.

As for why your log file is not being populated, I am not sure. What can I do to reproduce it? I’ve used your Caddyfile and cannot reproduce it. Any other tips?

Thanks. I apologize. I misspoke. I don’t really want it all to go to a file, just the “access” log part like caddy v1 did. (It’s just with all that JSON flooding my screen it’s hard to tell what I’m looking at. :slight_smile: )

As far as how to reproduce this I have no idea. I’ve tried every way I can think of to simplify & isolate. I’m just running it in my own account on this Ubuntu 19.10 box the same as I’ve been doing with caddy1 for quite a while now. I can ‘touch’ & ‘rm’ the access.log file from the same command prompt I’m running caddy2 from.

I moved everything into the same directory and now running it with this simple command: ./caddy2 run --config Caddyfile . I did the ‘validate’ subcommand and it returned happy.

But in every case it appears to just be ignoring the log directive. Neither the destination nor the format changes. With the log directive completely removed it behaves exactly the same as best I can tell.

I’d be totally gleeful if someone could point out where I’m doing something really dumb, but I’ve run out of ideas myself.

Do you have an suggestions on how to troubleshoot this?

1 Like

Nothing I can think of specifically to try. It should work, the log directive works on my system and Matt has apparently tested your Caddyfile verbatim working.

You’ve given us the Caddy version and your Caddyfile, but perhaps telling us more about the environment and how you specifically run Caddy might help us more accurately reproduce a setup that provokes this issue?


2. How I run Caddy:

a. System environment:

b. Command:

paste command here

c. Service/unit/compose file:

paste full file contents here

Thanks for offering to help.

$ uname -a
Linux mrh-laptop 5.3.0-42-generic #34-Ubuntu SMP Fri Feb 28 05:49:40 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
$ ls -lahtr
total 64M
drwx------ 10 michael michael 4.0K 2020-03-21 07:07:46 ..
-rw-r--r--  1 michael michael  323 2020-03-28 21:13:57 main.go
-rw-------  1 michael michael  805 2020-03-28 21:22:27 go.mod
-rw-------  1 michael michael  46K 2020-03-28 21:22:57 go.sum
-rwxr--r--  1 michael michael  32M 2020-03-29 17:57:49 caddy2_beta20_linux_amd64
-rwxr-xr-x  1 michael michael  32M 2020-03-29 17:57:49 caddy2
drwxr-xr-x  3 michael michael 4.0K 2020-03-30 13:25:56 bin
drwxr-xr-x  3 michael michael 4.0K 2020-03-30 13:28:21 .idea
drwxr-xr-x  4 michael michael 4.0K 2020-03-30 13:29:02 .
-rw-r--r--  1 michael michael  658 2020-03-30 13:29:09 Caddyfile
$ df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/nvme0n1p2  916G  449G  421G  52% /

Caddyfile (latest version):

http://localhost:2015, http://192.168.0.95:2015 {
	#log {
	#	output file         access.log
	#	format single_field common_log
	#}
	encode gzip
	
	handle /api/* {
		reverse_proxy localhost:8223
	}
	
	handle {
		root * ../frontend/dist
		try_files {path} /index.html
		file_server
	}
}

http://localhost:2016, http://192.168.0.95:2016 {
	log {
		output file access.log
		format single_field common_log
	}
	encode gzip
	
	handle /spi/* {
		reverse_proxy localhost:8224
	}
	
	handle {
		root * ../ctrl/dist
		try_files {path} /index.html
		file_server
	}
}
$ ./caddy2 version
v2.0.0-beta.20 h1:oUNG1uh0UV8LWLlAVDZolFzk112++V/pxY+fF0HLmlY=

Run caddy2:

$ ./caddy2 run --config Caddyfile 
2020/03/30 23:51:12.196	INFO	using provided configuration	{"config_file": "Caddyfile", "config_adapter": ""}
2020/03/30 23:51:12.199	INFO	admin	admin endpoint started	{"address": "localhost:2019", "enforce_origin": false, "origins": ["localhost:2019"]}
2020/03/30 18:51:12 [INFO][cache:0xc00077c6e0] Started certificate maintenance routine
2020/03/30 23:51:12.203	INFO	tls	cleaned up storage units
2020/03/30 23:51:12.203	INFO	autosaved config	{"file": "/home/michael/.config/caddy/autosave.json"}
2020/03/30 23:51:12.203	INFO	serving initial configuration

Hit one of the api end points on localhost:2016:

2020/03/30 23:52:24.886	ERROR	http.log.access	handled request	{"request": {"method": "GET", "uri": "/spi/poke", "proto": "HTTP/1.1", "remote_addr": "[::1]:38322", "host": "localhost:2016", "headers": {"Cache-Control": ["no-cache"], "Accept": ["application/json, text/plain, */*"], "Sec-Fetch-Dest": ["empty"], "User-Agent": ["Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/80.0.3987.149 Safari/537.36"], "Sec-Fetch-Mode": ["cors"], "Connection": ["keep-alive"], "Pragma": ["no-cache"], "Accept-Language": ["en-US,en;q=0.9"], "Sec-Fetch-Site": ["same-origin"], "Referer": ["http://localhost:2016/"], "Accept-Encoding": ["gzip, deflate, br"]}}, "common_log": "::1 - - [30/Mar/2020:18:52:24 -0500] \"GET /spi/poke HTTP/1.1\" 403 10", "latency": 0.001255023, "size": 10, "status": 403, "resp_headers": {"X-Content-Type-Options": ["nosniff"], "Date": ["Mon, 30 Mar 2020 23:52:24 GMT"], "Server": ["Caddy"], "Access-Control-Allow-Headers": ["Accept, Content-Type, Content-Length, Accept-Encoding, X-CSRF-Token, Authorization"], "Content-Type": ["text/plain; charset=utf-8"], "Content-Length": ["10"], "Access-Control-Allow-Credentials": ["true"], "Access-Control-Allow-Methods": ["POST, GET, OPTIONS, PUT, PATCH, DELETE"], "Access-Control-Allow-Origin": [""]}}

After login (skip that entry), hit the api endpoint again, and hit Ctrl-C to exit caddy2:

2020/03/30 23:54:41.296	INFO	http.log.access	handled request	{"request": {"method": "GET", "uri": "/spi/poke", "proto": "HTTP/1.1", "remote_addr": "[::1]:38322", "host": "localhost:2016", "headers": {"Sec-Fetch-Site": ["same-origin"], "Sec-Fetch-Mode": ["cors"], "Referer": ["http://localhost:2016/"], "Accept-Encoding": ["gzip, deflate, br"], "Connection": ["keep-alive"], "Cache-Control": ["no-cache"], "Accept": ["application/json, text/plain, */*"], "User-Agent": ["Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/80.0.3987.149 Safari/537.36"], "Cookie": ["STC-user=MTU4NTYxMjQ3NnxIQzlJZk1YdS05dkFNVzc5eFAtbFNpRWNaLVlmUEo5NThHWG9semd1RW0xSG1xcGdWdHFpQVZTNzBuM1FGUWJILVBkVFN2cXBnVmJFdnZWb19ZeWRDNEtRckdKODhEWFR8zfcV1MKVZvoL8a2fjXUXwluE396H_59OKyC0pjlu4xE="], "Pragma": ["no-cache"], "Sec-Fetch-Dest": ["empty"], "Accept-Language": ["en-US,en;q=0.9"]}}, "common_log": "::1 - - [30/Mar/2020:18:54:41 -0500] \"GET /spi/poke HTTP/1.1\" 200 0", "latency": 0.006221358, "size": 0, "status": 200, "resp_headers": {"Access-Control-Allow-Headers": ["Accept, Content-Type, Content-Length, Accept-Encoding, X-CSRF-Token, Authorization"], "Access-Control-Allow-Methods": ["POST, GET, OPTIONS, PUT, PATCH, DELETE"], "Access-Control-Allow-Origin": [""], "Date": ["Mon, 30 Mar 2020 23:54:41 GMT"], "Content-Length": ["0"], "Server": ["Caddy"], "Access-Control-Allow-Credentials": ["true"]}}
^C2020/03/30 23:55:11.283	INFO	shutting down	{"signal": "SIGINT"}
2020/03/30 18:55:11 [INFO][cache:0xc00077c6e0] Stopped certificate maintenance routine
2020/03/30 23:55:11.283	INFO	shutdown done	{"signal": "SIGINT"}

No access.log file:

$ ls -lahtr
total 64M
drwx------ 10 michael michael 4.0K 2020-03-21 07:07:46 ..
-rw-r--r--  1 michael michael  323 2020-03-28 21:13:57 main.go
-rw-------  1 michael michael  805 2020-03-28 21:22:27 go.mod
-rw-------  1 michael michael  46K 2020-03-28 21:22:57 go.sum
-rwxr--r--  1 michael michael  32M 2020-03-29 17:57:49 caddy2_beta20_linux_amd64
-rwxr-xr-x  1 michael michael  32M 2020-03-29 17:57:49 caddy2
drwxr-xr-x  3 michael michael 4.0K 2020-03-30 13:25:56 bin
drwxr-xr-x  3 michael michael 4.0K 2020-03-30 13:28:21 .idea
drwxr-xr-x  4 michael michael 4.0K 2020-03-30 13:29:02 .
-rw-r--r--  1 michael michael  658 2020-03-30 13:29:09 Caddyfile

I’m truly stumped. Yesterday (and many days before) I was running caddy1 from this same spot. I upgraded the Caddyfile to v2, downloaded caddy2 beta 20, and everything works except the log.

For completeness, here’s the caddy1 Caddyfile from before:

localhost, 192.168.0.95 {
    log
    gzip

    proxy /api localhost:8223
    proxy /api/v1/ws localhost:8223 { websocket }

    rewrite {
        # if {path} not_has api/
        if {path} not_starts_with /api/
        to {path} /
    }

    root ../frontend/dist
}

localhost:2016, 192.168.0.95:2016 {
    log
    gzip

    proxy /spi localhost:8224
    proxy /spi/ws localhost:8224 { websocket }

    rewrite {
        # if {path} not_has spi/
        if {path} not_starts_with /spi/
        to {path} /
    }

    root ../ctrl/dist
}
2 Likes

Thanks for the detailed reply! I was able to reproduce it this time. I think I know what’s going on…

1 Like

Fixed in httpcaddyfile: Include non-standard ports when mapping logger names · caddyserver/caddy@904d9ca · GitHub

Thanks again for your patience. The key was trying this on a site block with a key of http://localhost:2016 (specifically, a non-standard port), since requests for that site have a Host header value of localhost:2016 and not just localhost. Thus, mapping logger messages for that hostname failed to be attached to your custom log.

You can download the build artifacts from that commit to try it out!

2 Likes

Thank you! This does indeed seem to work.

Caddy2 writes a lot of stuff to stderr compared to caddy1. So I’ve got some work to do to figure out how to split things off but at least the access.log I’m used to is back now. Thanks again.

1 Like

You can further filter/tweak in the JSON: JSON Config Structure - Caddy Documentation

This article may help: How Logging Works — Caddy Documentation

1 Like

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