Multiple access logs in site block, only last defined works

Help
1

1. The problem I’m having:

I want to have multiple access logs (one similar to Common Log Format and another one with JSON) for a site block, but only the last one defined in the Caddyfile is working (= log file is created and http requests appear in the log file). The other file (from the first occurrence of the log directivce) is not even created.

When I remove the 2nd log directive for the JSON output, then the remaining log directive for the plain (similar to Common Log Format) is working and the defined log file name is created and http requests are stored.

But I can’t get two access logs working at the same time.

2. Error messages and/or full log output:

No error messages.

3. Caddy version:

v2.6.4 h1:2hwYqiRwk1tf3VruhMpLcYTg+11fCdr8S3jhNAdnPy8=

4. How I installed and ran Caddy:

Downloaded from Download Caddy with two extra features:

  • github.com/caddyserver/transform-encoder
  • github.com/ueffel/caddy-tls-format

a. System environment:

  • Oracle Linux 8.8
  • Linux instance-20221129-1409 5.15.0-102.110.5.1.el8uek.aarch64 #2 SMP Sat Jun 10 18:23:55 PDT 2023 aarch64 aarch64 aarch64 GNU/Linux

b. Command:

./caddy start
curl -I http://localhost:18080/
ls -l access-localhost.*
# Only access-localhost.json exists, but I expect access-localhost.log as well

c. Service/unit/compose file:

not applicape

d. My complete Caddy config:

{
        http_port 18080
        debug
}
localhost:18080 {
        log {
                output file access-localhost.log
                format filter {
                        wrap formatted "[{ts}] {request>remote_ip} {request>headers>X-Forwarded-For} {request>method} {request>host}{request>uri} {status} {request>headers>User-Agent>[0]} {request>headers>Referer} {http>auth>user>id} {request>tls>version} {request>tls>cipher_suite}" {
                                time_format "02.01.2006 15:04:05"
                                time_local
                        }
                        fields {
                                request>tls>version tls_version TLSv
                                request>tls>cipher_suite tls_cipher
                        }
                }
        }

        log {
                output file access-localhost.json
                format filter {
                        wrap json
                        fields {
                                request>tls>version tls_version TLSv
                                request>tls>cipher_suite tls_cipher
                        }
                }
        }

        respond "{http.request.uri}?{http.request.uri.query} {time.now.unix_ms}"
}

5. Links to relevant resources:

2

Unfortunately, this is non-trivial to configure with the Caddyfile. It’s possible, but it can be flaky.

The problem is with how the Caddyfile transforms your config into a JSON config that Caddy actually runs with. Technically, logging is “global” configuration, but we do some magic to hoist per-site access log config to the top-level logging config.

Run caddy adapt --pretty --config /path/to/Caddyfile to see how it looks in JSON config.

Basically you’d need to enable access logging once with log (no options) in the site, and then configure the one or more log in global options with unique names, and in those, include the access logs by name (i.e. http.log.access.log0 depending on whatever logger name the Caddyfile adapter chose, depending on the order of sites in your Caddyfile).

This is flaky because there’s currently no way to set the logger name that the log directive (inside a site block) will use, and it’ll always use the auto-generated name like log0 or log1 etc, so if you change your config such that it uses a different number (e.g. adding anothe site above that one or whatever), your logs might be written to the wrong file.

3

Thank you very much @francislavoie for your help. Appreciate it.

I have run ./caddy adapt --pretty --config Caddyfile | jq and got this output (and stored as caddy.json)

{
  "logging": {
    "logs": {
      "default": {
        "level": "DEBUG",
        "exclude": [
          "http.log.access.log0",
          "http.log.access.log1"
        ]
      },
      "log0": {
        "writer": {
          "filename": "access-localhost.log",
          "output": "file"
        },
        "encoder": {
          "fields": {
            "request>tls>cipher_suite": {
              "filter": "tls_cipher"
            },
            "request>tls>version": {
              "filter": "tls_version",
              "prefix": "TLSv"
            }
          },
          "format": "filter",
          "wrap": {
            "format": "formatted",
            "template": "[{ts}] {request>remote_ip} {request>headers>X-Forwarded-For} {request>method} {request>host}{request>uri} {status} {request>headers>User-Agent>[0]} {request>headers>Referer} {http>auth>user>id} {request>tls>version} {request>tls>cipher_suite}",
            "time_format": "02.01.2006 15:04:05",
            "time_local": true
          }
        },
        "level": "DEBUG",
        "include": [
          "http.log.access.log0"
        ]
      },
      "log1": {
        "writer": {
          "filename": "access-localhost.json",
          "output": "file"
        },
        "encoder": {
          "fields": {
            "request>tls>cipher_suite": {
              "filter": "tls_cipher"
            },
            "request>tls>version": {
              "filter": "tls_version",
              "prefix": "TLSv"
            }
          },
          "format": "filter",
          "wrap": {
            "format": "json"
          }
        },
        "level": "DEBUG",
        "include": [
          "http.log.access.log1"
        ]
      }
    }
  },
  "apps": {
    "http": {
      "http_port": 18080,
      "servers": {
        "srv0": {
          "listen": [
            ":18080"
          ],
          "routes": [
            {
              "match": [
                {
                  "host": [
                    "localhost"
                  ]
                }
              ],
              "handle": [
                {
                  "handler": "subroute",
                  "routes": [
                    {
                      "handle": [
                        {
                          "body": "{http.request.uri}?{http.request.uri.query} {time.now.unix_ms}",
                          "handler": "static_response"
                        }
                      ]
                    }
                  ]
                }
              ],
              "terminal": true
            }
          ],
          "logs": {
            "logger_names": {
              "localhost:18080": "log1"
            }
          }
        }
      }
    }
  }
}

How should I modify that caddy.json in order to have both of my access-log configuration work?

Would you suggest to change the lower part from

          "logs": {
            "logger_names": {
              "localhost:18080": "log1"
            }

into this?

         "logs": {
            "logger_names": {
              "localhost:18080": "log1",
              "localhost:18080": "log0"
            }

I did this and started caddy with caddy run --config caddy.json but now again only the configuration for “log0”, which is the “access-localhost.log” is created, but not the other one for “access-localhost.json”.

I’m stuck. Any help appreciated.

4

I was describing a config like this, essentially:

{
	log access-formatted {
		include http.log.access.log0
		output file access-localhost.log
		format console
	}

	log access-json {
		include http.log.access.log0
		output file access-localhost.json
		format json
	}
}

localhost:8881 {
	log
}

But I realized after a bit of testing that this doesn’t work as-is because the log directive when used without any output/format config does not actually generate log0 and it instead just uses empty string as the logger (try it with caddy adapt --pretty and you’ll see what I mean, it has "localhost:8881": "" instead of what I was expecting, "localhost:8881": "log0", under logger_names).

That said, I decided to implement logger name overrides, I added it to my existing PR httpcaddyfile: Allow `hostnames` & logger name overrides for log directive by francislavoie · Pull Request #5643 · caddyserver/caddy · GitHub, see the second commit.

So this makes it possible to do this – same as above, but overrides the logger name with log foo in the site block, and include-ing that logger with http.log.access.foo:

{
	log access-formatted {
		include http.log.access.foo
		output file access-localhost.log
		format console
	}

	log access-json {
		include http.log.access.foo
		output file access-localhost.json
		format json
	}
}

localhost:8881 {
	log foo
}

I tested this, and it works well; a single HTTP requests produces two separate log files with different formats.

1 Like
5

Thanks for your swift reply @francislavoie and the examples provided and your commit on GitHub.

Will it be possible to use import in the global options to set up many log directives with two small include files?
I am thinking about this:

File: include-access-formatted.caddy, which contains:

log access-formatted-{args.0} {
        include http.log.access.{args.0}
        output file logs/access-{args.0}.log
        format filter {
                wrap formatted "[{ts}] {request>remote_ip} {request>headers>X-Forwarded-For} {request>method} {request>host}{request>uri} {status} {request>headers>User-Agent>[0]} {request>headers>Referer} {http>auth>user>id} {request>tls>version} {request>tls>cipher_suite}" {
                        time_format "02.01.2006 15:04:05"
                        time_local
                }
                fields {
                        request>tls>version tls_version TLSv
                        request>tls>cipher_suite tls_cipher
                }
        }
}

File: include-access-json.caddy, which contains:

log access-json-{args.0} {
        include http.log.access.{args.0}
        output file logs/access-{args.0}.json
        format filter {
                wrap json
                fields {
                        request>tls>version tls_version TLSv
                        request>tls>cipher_suite tls_cipher
                }
        }
}

Then I would reuse these include files for each site block

{
	import include-access-formatted.caddy example.com
	import include-access-json.caddy example.com

	import include-access-formatted.caddy example.de
	import include-access-json.caddy example.de
}

example.com, www.example.com:8080 {
  log example.com

  respond "Thank you!"
}

example.de:8080 {
  log example.de

  respond "Thank you!"
}

And I would expect that a HTTP Request to www.example.com:8080/test is logged in

  • logs/access-example.com.log
  • logs/access-example.com.json

And a HTTP Request to example.de:8080/test2 is logged in

  • logs/access-example.de.log
  • logs/access-example.de.json

Or should one better not use . in names and use _ instead, such as log example_de ?

BTW: Where can I find an instruction how to build caddy with xcaddy for the Github PR of yours?

I tried this:

# ./xcaddy build --with github.com/caddyserver/caddy/v2=github.com/caddyserver/caddy@log-hostname-override
2023/07/25 19:37:50 [INFO] Temporary folder: /tmp/buildenv_2023-07-25-1937.809161089
2023/07/25 19:37:50 [INFO] Writing main module: /tmp/buildenv_2023-07-25-1937.809161089/main.go
package main

import (
        caddycmd "github.com/caddyserver/caddy/v2/cmd"

        // plug in Caddy modules here
        _ "github.com/caddyserver/caddy/v2/modules/standard"
        _ "github.com/caddyserver/caddy/v2"
)

func main() {
        caddycmd.Main()
}
2023/07/25 19:37:50 [INFO] Initializing Go module
2023/07/25 19:37:50 [INFO] exec (timeout=-2562047h47m16.854775808s): /usr/bin/go mod init caddy
go: creating new go.mod: module caddy
go: to add module requirements and sums:
        go mod tidy
2023/07/25 19:37:50 [INFO] Replace github.com/caddyserver/caddy/v2 => github.com/caddyserver/caddy@log-hostname-override
2023/07/25 19:37:50 [INFO] exec (timeout=-2562047h47m16.854775808s): /usr/bin/go mod edit -replace github.com/caddyserver/caddy/v2=github.com/caddyserver/caddy@log-hostname-override
2023/07/25 19:37:50 [INFO] Pinning versions
2023/07/25 19:37:50 [INFO] exec (timeout=-2562047h47m16.854775808s): /usr/bin/go get -d -v github.com/caddyserver/caddy/v2
go: errors parsing go.mod:
/tmp/buildenv_2023-07-25-1937.809161089/go.mod:5: replace github.com/caddyserver/caddy: version "v0.0.0-20230725182109-017d63aad4cf" invalid: go.mod has post-v0 module path "github.com/caddyserver/caddy/v2" at revision 017d63aad4cf
2023/07/25 19:38:06 [FATAL] exit status 1
6

Close, you need /v2 on the replacement as well:

xcaddy build --with github.com/caddyserver/caddy/v2=github.com/caddyserver/caddy/v2@log-hostname-override

And make sure you’re using Go 1.20.6+

Also FYI {args.0} syntax is deprecated in the upcoming version, you’ll want to use {args[0]} instead to avoid a warning.

(P.S. your example only uses your 0th arg, you probably wanted to use your 1th arg too?)

Yeah nothing stopping you from using dots I think, but dots do have a particular meaning for logger names so maybe you should avoid it if you can. Should still work anyway. The dots are just for hierarchy/namespacing with include/exclude so you can use a higher level name to include everything below that level.

2 Likes
7

Thank you very much, @francislavoie.

With your help, I was able to build caddy based on your last commit 017d63aad4cfde8e3907affa16501151931d274e.

I tested it, and eventually I was able to get it working :smile:
Thank you very much. Looking forward to the next Caddy release.

During my tests with that binary, I have often received an exception. I was able to track it down a bit and if the Caddyfile contains debug in the global options, the exception is raised.

[root@d92240ab6e99 bin]# cat Caddyfile_francis_exception
{
        debug

        log access-formatted {
                include http.log.access.foo
                output file access-localhost.log
                format console
        }

        log access-json {
                include http.log.access.foo
                output file access-localhost.json
                format json
        }
}

localhost:8881 {
        log foo
}

[root@d92240ab6e99 bin]# ./caddy run --config Caddyfile_francis_exception
2023/07/26 08:33:25.023 INFO    using provided configuration    {"config_file": "Caddyfile_francis_exception", "config_adapter": ""}
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x38 pc=0xd5adec]

goroutine 1 [running]:
github.com/caddyserver/caddy/v2/caddyconfig/httpcaddyfile.ServerType.Setup.func1({{0x4000686948, 0x3}, {0x25cf560, 0x0, 0x0}, 0x0})
        github.com/caddyserver/caddy/v2@v2.6.4/caddyconfig/httpcaddyfile/httptype.go:245 +0xac
github.com/caddyserver/caddy/v2/caddyconfig/httpcaddyfile.ServerType.Setup({}, {0x4000682880, 0x2, 0x40005f17d0?}, 0x40005f1740)
        github.com/caddyserver/caddy/v2@v2.6.4/caddyconfig/httpcaddyfile/httptype.go:275 +0x1b04
github.com/caddyserver/caddy/v2/caddyconfig/caddyfile.Adapter.Adapt({{0x194a340?, 0x25cf560?}}, {0x40000ca400, 0xfd, 0x200}, 0x40005fac60?)
        github.com/caddyserver/caddy/v2@v2.6.4/caddyconfig/caddyfile/adapter.go:50 +0xf0
github.com/caddyserver/caddy/v2/cmd.loadConfigWithLogger(0x400024b730, {0xffffef1938ed, 0x1b}, {0x0, 0x0})
        github.com/caddyserver/caddy/v2@v2.6.4/cmd/main.go:161 +0x5d8
github.com/caddyserver/caddy/v2/cmd.LoadConfig({0xffffef1938ed, 0x1b}, {0x0, 0x0})
        github.com/caddyserver/caddy/v2@v2.6.4/cmd/main.go:92 +0x40
github.com/caddyserver/caddy/v2/cmd.cmdRun({0x0?})
        github.com/caddyserver/caddy/v2@v2.6.4/cmd/commandfuncs.go:205 +0x538
github.com/caddyserver/caddy/v2/cmd.WrapCommandFuncForCobra.func1(0x4000222600?, {0x14aa487?, 0x2?, 0x2?})
        github.com/caddyserver/caddy/v2@v2.6.4/cmd/cobra.go:126 +0x30
github.com/spf13/cobra.(*Command).execute(0x4000222600, {0x40005d86e0, 0x2, 0x2})
        github.com/spf13/cobra@v1.7.0/command.go:940 +0x5c4
github.com/spf13/cobra.(*Command).ExecuteC(0x25720c0)
        github.com/spf13/cobra@v1.7.0/command.go:1068 +0x340
github.com/spf13/cobra.(*Command).Execute(...)
        github.com/spf13/cobra@v1.7.0/command.go:992
github.com/caddyserver/caddy/v2/cmd.Main()
        github.com/caddyserver/caddy/v2@v2.6.4/cmd/main.go:64 +0x68
main.main()
        caddy/main.go:14 +0x1c
[root@d92240ab6e99 bin]#

When I remove the debug directive, caddy runs fine:

[root@d92240ab6e99 bin]# cat Caddyfile_francis
{
        log access-formatted {
                include http.log.access.foo
                output file access-localhost.log
                format console
        }

        log access-json {
                include http.log.access.foo
                output file access-localhost.json
                format json
        }
}

localhost:8881 {
        log foo
}
[root@d92240ab6e99 bin]# ./caddy run --config Caddyfile_francis
2023/07/26 08:35:13.625 INFO    using provided configuration    {"config_file": "Caddyfile_francis", "config_adapter": ""}
2023/07/26 08:35:13.627 INFO    admin   admin endpoint started  {"address": "localhost:2019", "enforce_origin": false, "origins": ["//localhost:2019", "//[::1]:2019", "//127.0.0.1:2019"]}
2023/07/26 08:35:13.627 INFO    http.auto_https enabling automatic HTTP->HTTPS redirects        {"server_name": "srv0"}
2023/07/26 08:35:13.627 INFO    tls.cache.maintenance   started background certificate maintenance      {"cache": "0x40006d7f80"}
2023/07/26 08:35:13.628 INFO    tls     cleaning storage unit   {"description": "FileStorage:/root/.local/share/caddy"}
2023/07/26 08:35:13.628 INFO    tls     finished cleaning storage units
2023/07/26 08:35:13.642 INFO    pki.ca.local    root certificate is already trusted by system   {"path": "storage:pki/authorities/local/root.crt"}
2023/07/26 08:35:13.642 INFO    http    enabling HTTP/3 listener        {"addr": ":8881"}
2023/07/26 08:35:13.643 INFO    http.log        server running  {"name": "srv0", "protocols": ["h1", "h2", "h3"]}
2023/07/26 08:35:13.643 INFO    http.log        server running  {"name": "remaining_auto_https_redirects", "protocols": ["h1", "h2", "h3"]}
2023/07/26 08:35:13.643 INFO    http    enabling automatic TLS certificate management   {"domains": ["localhost"]}
2023/07/26 08:35:13.644 WARN    tls     stapling OCSP   {"error": "no OCSP stapling for [localhost]: no OCSP server specified in certificate", "identifiers": ["localhost"]}
2023/07/26 08:35:13.644 INFO    autosaved config (load with --resume flag)      {"file": "/root/.config/caddy/autosave.json"}
2023/07/26 08:35:13.644 INFO    serving initial configuration
^C
[root@d92240ab6e99 bin]#

Go version is go version go1.20.6 linux/arm64.

Shall I add this comment on the PR on github?

8

Yes, please leave a comment on GitHub, I’ll look into it after my vacation (gone til Sunday). Thanks!

1 Like
9

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