Format Errors with Caddy JSON

[Robert-Ernst]

I confirm issues with Caddy JSON too. I'm new to the project and my first experience is that it's not working.

goaccess -V
GoAccess - 1.5.5.

OS:
Ubuntu 22.04.2 LTS

Command:
goaccess /docker/caddy/log/myLog.log --no-ip-validation --log-format CADDY

Relevant part of the Caddyfile

        log {
                output file /var/log/myLog.log
                format json
        }

Output:

Cleaning up resources...
==2851435== GoAccess - Copyright (C) 2009-2020 by Gerardo Orellana
==2851435== https://goaccess.io - <hello@goaccess.io>
==2851435== Released under the MIT License.
==2851435==
==2851435== FILE: /docker/caddy/log/myLog.log
==2851435== Parsed 10 lines producing the following errors:
==2851435==
==2851435== IPv4/6 is required.
==2851435== IPv4/6 is required.
==2851435== IPv4/6 is required.
==2851435== IPv4/6 is required.
==2851435== IPv4/6 is required.
==2851435== IPv4/6 is required.
==2851435== IPv4/6 is required.
==2851435== IPv4/6 is required.
==2851435== IPv4/6 is required.
==2851435== IPv4/6 is required.
==2851435==
==2851435== Format Errors - Verify your log/date/time format

[Robert-Ernst]

I just updated as described on the Readme and the error still remains the same:

goaccess -V
GoAccess - 1.9.1.

[allinurl]

Thanks for giving me the heads up on this. Sounds like the default log format isn't quite right. Bummer that I missed it in today's v1.91 release. I'll make sure to include it in the next one. This probably ties into #2601. Anyway, are you able to submit a PR with the right format for this? The relevant lines are here and here. Thanks a bunch!

[Teqed]

I was setting up GoAccess for Caddy today and ran into this as well, but only when configuring Caddy's global log option and asking GoAccess to read it. If you setup only access logging on your domains it should work, and I think GoAccess's default Caddy configuration only expects these logs.

Example Caddyfile:

{ #Global Options
	log {
		# Don't configure your access log here...
	}
}
example.com {
	log {
		# Configure your access logs here.
		output file /var/log/caddy/access.log
	}
	# ...
}

If you have multiple domains, you can use snippets to make things easier.

Then read the log with goaccess:

sudo goaccess /var/log/caddy/access.log --log-format=CADDY

Tested with Caddy v2.7.6 and GoAccess 1.9.1. If the above still gives you any trouble, it might be helpful to include your Caddy version as well.

I don't think this is related to #2601 exactly, which is its own issue that originates with Caddy receiving first-class support for logging client IPs (such as from 'X-Forwared-For' headers) where the typical user might want to see the client_ip instead of remote_ip in the "Visitor Hostnames and IPs" table.

[allinurl]

Hey @Teqed, thanks for catching that and providing the details. I'm thinking, should we consider adding another predefined option for when it's configured globally, like maybe CADDY_GLOBAL? Thoughts?

[allinurl]

actually, looking at my response again, the global approach might be trickier since it doesn't appear to be a valid JSON string, as far as I can tell?

[Robert-Ernst]

I attached a censored example entry from a global debug level log.
The JSON seems pretty valid to me:

{
    "level": "debug",
    "ts": 1707272627.5637116,
    "logger": "http.handlers.reverse_proxy",
    "msg": "upstream roundtrip",
    "upstream": "xxxx:8080",
    "duration": 0.00726643,
    "request": {
        "remote_ip": "131.191.11.111",
        "remote_port": "51987",
        "client_ip": "131.191.11.111",
        "proto": "HTTP/2.0",
        "method": "GET",
        "host": "xxxxx.xx",
        "uri": "/config",
        "headers": {
            "Referer": [
                "https://xxxx.xxxxxxx.xx/"
            ],
            "Sec-Fetch-Dest": [
                "empty"
            ],
            "X-Forwarded-For": [
                "131.191.11.111"
            ],
            "Sec-Fetch-Site": [
                "same-origin"
            ],
            "Te": [
                "trailers"
            ],
            "Accept": [
                "application/json, text/plain, */*"
            ],
            "X-Forwarded-Host": [
                "xxxxx.xx"
            ],
            "Dnt": [
                "1"
            ],
            "X-Clientapp": [
                "web_client"
            ],
            "X-Forwarded-Proto": [
                "https"
            ],
            "Accept-Encoding": [
                "gzip, deflate, br"
            ],
            "Sec-Gpc": [
                "1"
            ],
            "Sec-Fetch-Mode": [
                "cors"
            ],
            "User-Agent": [
                "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:121.0) Gecko/20100101 Firefox/121.0"
            ],
            "Accept-Language": [
                "en-US,en;q=0.5"
            ]
        },
        "tls": {
            "resumed": false,
            "version": 772,
            "cipher_suite": 4865,
            "proto": "h2",
            "server_name": "xxxxx.xx"
        }
    },
    "headers": {
        "Date": [
            "Wed, 07 Feb 2024 02:23:47 GMT"
        ],
        "Content-Length": [
            "657"
        ],
        "Content-Type": [
            "text/plain; charset=utf-8"
        ]
    },
    "status": 200
}

[Robert-Ernst]

I attached a censored example entry from a local debug level log.
The JSON seems to have the same format as the previous one.
The local configuration works with goaccess. I just confirmed it.

{
    "level": "info",
    "ts": 1707273079.4037006,
    "logger": "http.log.access.log0",
    "msg": "handled request",
    "request": {
        "remote_ip": "11.111.1.111",
        "remote_port": "45873",
        "client_ip": "11.111.1.111",
        "proto": "HTTP/1.1",
        "method": "GET",
        "host": "xxxxx.xx",
        "uri": "xxxx/xxxxx/xxxxx",
        "headers": {
            "Connection": [
                "close"
            ],
            "User-Agent": [
                "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:103.0) Gecko/20100101 Firefox/103.0"
            ],
            "Accept": [
                "text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8"
            ],
            "Accept-Language": [
                "en-us,en-gb,en;q=0.7,*;q=0.3"
            ],
            "Accept-Encoding": [
                "gzip"
            ]
        },
        "tls": {
            "resumed": false,
            "version": 772,
            "cipher_suite": 4865,
            "proto": "http/1.1",
            "server_name": "xxxxx.xx"
        }
    },
    "bytes_read": 0,
    "user_id": "",
    "duration": 0.002669453,
    "size": 3436,
    "status": 200,
    "resp_headers": {
        "Accept-Ranges": [
            "bytes"
        ],
        "Last-Modified": [
            "Fri, 07 Jul 2023 10:33:07 GMT"
        ],
        "Cache-Control": [
            "public, max-age=0"
        ],
        "Content-Length": [
            "3436"
        ],
        "Server": [
            "Caddy"
        ],
        "Alt-Svc": [
            "h3=\":443\"; ma=2592000"
        ],
        "Content-Type": [
            "text/html; charset=UTF-8"
        ],
        "Date": [
            "Wed, 07 Feb 2024 02:31:19 GMT"
        ],
        "Etag": [
            "W/\"d6c-1892fe9a07a\""
        ]
    }
}

[Robert-Ernst]

As seen in my example I kinda compare oranges and apples. One is a debug level event the other one an info level event.
My guesswork would be that there are some entries (especially in debug logging) which maybe disturbs the parser. But that the "regular" entries working fine. Tbh I have no clue what goaccess does in the background.

[allinurl]

@Robert-Ernst, I was looking at this and noticed some differences between fields like resp_headers vs headers. But it seems like it should work fine for both entries for the most part (see screenshot). The default GoAccess format for CADDY is indeed the 'local/info' format, as you mentioned. However, if necessary, you can customize the log format that GoAccess uses to align with your specific configuration. Making this adjustment is relatively simple.

Are you still encountering any issues in the latest version?

[Robert-Ernst]

It works for me in the local info format.
Not with the global one. But that is fine.
I would recommend adding this information to the documentation and this should be fine.
As Teqed suggested it's possible to create snippets and thus local configuration is easily customizable in Caddy.
After the documentation has been created, you can close this ticket.

[allinurl]

Appreciate the feedback. I've made the necessary updates to both the man page and the documentation on the website regarding the log-format configuration.

Closing this, feel free to reopen it if necessary.

[Teqed]

While it's on my mind, I wanted to mention that I think there may be a way to configure logs globally the way we're expecting by including only access log events:

# Globals
{
	log global_access {
		output file /var/log/caddy/access.log
		include http.log.access
	}
}

By using the include directive only available at the global log level, we're able to filter to only the log format we expect, and are able to log across all domains without individually configuring each. I haven't ran this for more than a few minutes to make sure it works at expected, but assuming it does, this is probably the solution most people will want.

It might also be useful for someone to consume Caddy's non-http.log.access events -- which often describe application status, SSL certificate negotiations, configuration reloads, etc. -- but making use of Caddy's complete log would be a different dashboard serving a different purpose.