Access Logging in Spring Boot

[scionaltera]

I've been working on getting a copy of Agony Forge up and running on a machine at my house, doing port forwarding from my router. I'm pretty good at this kind of stuff but I was having trouble with getting the websocket connection returning 403s. I thought to myself, "You know, it would be handy to have the access logs from Tomcat so I could see if the connection was getting all the way through or not. I'll just turn those on."

I found an article online that said you just need to add the following to application.yaml:

server:
  tomcat:
    accesslog:
      enabled: true

Great! That was easy! But... where are my logs? I don't see them.

It turns out they are written to a file with a randomly assigned filename in /tmp inside the docker container. I was able to get into the container and find them when I ran it on my laptop, but doing that on the other machine is complicated for various reasons. Popping inside that container is not going to be a feasible thing to do on a regular basis. I really needed them to just be there with all my other logs. Apparently, this is not a straightforward thing to do in Spring Boot 3.

I spent many hours fiddling around with something called a LogbackValve, which attaches to Tomcat and pipes the logs out. It reads a configuration file named conf/logback-access.xml by default, although the filename is configurable. I figured that would be the end of it: configure a ConsoleAppender in the config file and log the access logs to the console. In my environment those messages would be visible along with the other logs. Sadly, it was not that simple at all.

First, Logback complained that the "common" pattern I was using in the configuration (literally the default) was invalid. It turns out that Spring Boot reconfigures Logback so hard that it doesn't recognize its own default configuration anymore. If you check out Agony Forge's GitHub you can find my logback-access.xml in which I redefine all the default conversion patterns in addition to including Spring Boot's default configuration for all the fancy colors and stuff that it does. Fun stuff!

Next, Logback complained about a ClassCastException because it couldn't cast an ILoggingEvent to an IAccessEvent. After a couple more hours of reading articles, documentation and poking through the code for Logback I realized there are two distinct types of log messages in Logback: regular logging events and "access" events. There are also two distinct kinds of Appenders for those events that are not compatible with one another. Because many applications have a very high volume of "access" events, they never built a ConsoleAppender for access events. If your website has very much traffic, it would be too slow. I get that logic and agree with it in principle, but in this case it very much does not apply.

So I wrote my own AccessLogAppender in Agony Forge. It's very simple, and loosely based on the ConsoleAppender. The clever part is that when it receives an IAccessEvent it formats it according to the configuration and then... logs it to the regular game's logger. Now I'm sure you're asking, "isn't that inefficient?" and "won't that be slow?" and the answer is yes. If you have a large volume of HTTP traffic you do not want this to be turned on. In my case there are two reasons it's not a big deal:

1. The amount of traffic I am receiving is basically zero, and I'm just using it for debugging network issues.
2. Once a player has logged in and moved over to Websockets, they don't generate any more access log messages. So most of the time even on a busy MUD there still wouldn't be a lot of these messages.

Fortunately there are a couple of ways to turn it off if you need to.

1. It logs at DEBUG so you can just turn it off in application.yaml.
2. If that's not enough, you can turn it off by disabling the LogbackValve in TomcatConfiguration.

Anyway, that was my adventure with Logback in Spring Boot. Given how few articles I could find about this stuff that weren't either extremely basic or ten years old, I imagine this could be helpful to someone out there.

[scionaltera]

In case you were curious, I did eventually figure out why I kept getting 403s. When setting up the reverse proxy on my NAS, there's a setting you have to set to configure the headers it needs to support WebSockets. Without them, you get 403s when it tries to upgrade the connection from HTTPS.