search

bayang / jelu

Self hosted read and to-read list book tracker
MIT License
331 stars 13 forks source link

Best way to enable and see logs when Tomcat serves HTTP 400 error #66

Closed gene1wood closed 1 year ago

gene1wood commented 1 year ago

This may just be a request for some additional detail in the documentation (which I'm happy to PR once I figure this out) on how to get logs out of jelu.

I've deployed jelu using the docker container behind Authelia and SWAG (an Nginx reverse proxy).

When I browse to jelu through SWAG I get a HTTP 400 error back from Tomcat. The jelu.log file mentioned in the docs doesn't create a new log line when the 400 is served.

Here is what the request that is arriving at jelu looks like (I used docker-http-https-echo to see what a request being passed through SWAG after Authelia authentication looks like)

{
  "path": "/",
  "headers": {
    "remote-user": "jdoe",
    "remote-groups": "admins,jelu",
    "remote-name": "John Doe",
    "remote-email": "jdoe@example.com",
    "connection": "close",
    "host": "jelu.example.com",
    "x-forwarded-for": "192.168.0.105",
    "x-forwarded-host": "jelu.example.com:443, jelu.example.com",
    "x-forwarded-method": "GET",
    "x-forwarded-proto": "https",
    "x-forwarded-server": "jelu.example.com",
    "x-forwarded-ssl": "on",
    "x-forwarded-uri": "/",
    "x-original-url": "https://jelu.example.com/",
    "x-real-ip": "192.168.1.105",
    "user-agent": "Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/111.0",
    "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,*/*;q=0.8",
    "accept-language": "en-US,en;q=0.5",
    "accept-encoding": "gzip, deflate, br",
    "upgrade-insecure-requests": "1",
    "sec-fetch-dest": "document",
    "sec-fetch-mode": "navigate",
    "sec-fetch-site": "same-site",
    "sec-fetch-user": "?1",
    "cookie": "authelia_session=BWy-REDACTED-onb"
  },
  "method": "GET",
  "body": "",
  "fresh": false,
  "hostname": "jelu.example.com",
  "ip": "192.168.1.105",
  "ips": [
    "192.168.1.105"
  ],
  "protocol": "https",
  "query": {},
  "subdomains": [
    "jelu"
  ],
  "xhr": false,
  "os": {
    "hostname": "f27ee356b422"
  },
  "connection": {}
}

And my application.yml contains

jelu:
  auth:
    proxy:
      enabled: true
      adminName: "jdoe"
      header: Remote-User  # https://github.com/linuxserver/docker-swag/blob/ce32306873ded414980e60d9c46eb87464ce2f3b/root/defaults/nginx/authelia-location.conf.sample#L20
    ldap:
      enabled: false
server:
  port: 8400

I've confirmed that if I bypass SWAG and Authelia and just do a curl -i http://jelu:8400 from the SWAG container, I get a HTTP 200 and HTML from jelu, so there's something about the request after it goes through SWAG that is causing jelu to choke.

So my main question is, how do I enable additional logging to see why it is that Tomcat is returning an HTTP 400 when I browse to jelu through SWAG?

bayang commented 1 year ago

Okay, I'll try to have a look when I have some time. Just know that your exact setup does work, since someone else already opened an issue for it : #64 A 400 http code is weird, because it has nothing to do with authentication, it is just a bad request.

In the meantime, if you want the tomcat access logs you can have a look at this : https://www.baeldung.com/spring-boot-embedded-tomcat-logs

Which basically is : add server.tomcat.accesslog.enabled=true somewhere (as an env variable or in your yaml config file) and if you really need to delve into tomcat internals, you want to add : 

logging.level.org.apache.tomcat=DEBUG
logging.level.org.apache.catalina=DEBUG

again, as env vars or in your yaml.

But I think access logs should already be useful.

Also you can start by making sure you application.yml file is really picked by the jelu app in your container (ie check your volumes)

gene1wood commented 1 year ago

Thanks for that guidance.

Also you can start by making sure you application.yml file is really picked by the jelu app in your container (ie check your volumes)

I feel confident it is as I set the server port in application.yml and I then see in the container output from the app

2023-04-06 04:25:52.721  INFO 1 --- [main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8400 (http) with context path ''

Implying that the file is being read.

I first enabled just access logs which write out to /tmp/tomcat.8400.17324305235024466065/log/access_log.*.log

Those access logs show the 400 but don't give much more information

172.21.0.4 - - [06/Apr/2023:04:36:23 +0000] "GET / HTTP/1.1" 400 435

So I then set the tomcat and catalina logging level to DEBUG. This produced additional log lines in the docker container output.

Log lines from application startup

Of the various log lines that show up on application start, these two seem potentially noteworthy, though, given that they're of log level DEBUG they may also be innocuous.

org.apache.tomcat.jni.LibraryNotFoundError: Can't load library: /app/bin/libtcnative-2.so

Full log lines ``` 2023-04-06 04:32:03.022 DEBUG 1 --- [main] o.a.catalina.core.AprLifecycleListener : The Apache Tomcat Native library could not be found using names [tcnative-2, libtcnative-2, tcnative-1, libtcnative-1] on the java.library.path [/usr/java/packages/lib:/usr/lib64:/lib64:/lib:/usr/lib]. The errors reported were [Can't load library: /app/bin/libtcnative-2.so, Can't load library: /app/bin/liblibtcnative-2.so, Can't load library: /app/bin/libtcnative-1.so, Can't load library: /app/bin/liblibtcnative-1.so, no tcnative-2 in java.library.path: [/usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib], no libtcnative-2 in java.library.path: [/usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib], no tcnative-1 in java.library.path: [/usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib], no libtcnative-1 in java.library.path: [/usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib]] org.apache.tomcat.jni.LibraryNotFoundError: Can't load library: /app/bin/libtcnative-2.so, Can't load library: /app/bin/liblibtcnative-2.so, Can't load library: /app/bin/libtcnative-1.so, Can't load library: /app/bin/liblibtcnative-1.so, no tcnative-2 in java.library.path: [/usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib], no libtcnative-2 in java.library.path: [/usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib], no tcnative-1 in java.library.path: [/usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib], no libtcnative-1 in java.library.path: [/usr/java/packages/lib, /usr/lib64, /lib64, /lib, /usr/lib] at org.apache.tomcat.jni.Library.(Library.java:93) ~[tomcat-embed-core-9.0.69.jar:9.0.69] at org.apache.tomcat.jni.Library.initialize(Library.java:234) ~[tomcat-embed-core-9.0.69.jar:9.0.69] at org.apache.catalina.core.AprLifecycleListener.init(AprLifecycleListener.java:201) ~[tomcat-embed-core-9.0.69.jar:9.0.69] at org.apache.catalina.core.AprLifecycleListener.isAprAvailable(AprLifecycleListener.java:112) ~[tomcat-embed-core-9.0.69.jar:9.0.69] at org.springframework.boot.web.embedded.tomcat.TomcatServletWebServerFactory.getDefaultServerLifecycleListeners(TomcatServletWebServerFactory.java:182) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.web.embedded.tomcat.TomcatServletWebServerFactory.(TomcatServletWebServerFactory.java:129) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.autoconfigure.web.servlet.ServletWebServerFactoryConfiguration$EmbeddedTomcat.tomcatServletWebServerFactory(ServletWebServerFactoryConfiguration.java:76) ~[spring-boot-autoconfigure-2.7.6.jar:2.7.6] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Unknown Source) ~[na:na] at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:154) ~[spring-beans-5.3.24.jar:5.3.24] at org.springframework.beans.factory.support.ConstructorResolver.instantiate(ConstructorResolver.java:653) ~[spring-beans-5.3.24.jar:5.3.24] at org.springframework.beans.factory.support.ConstructorResolver.instantiateUsingFactoryMethod(ConstructorResolver.java:638) ~[spring-beans-5.3.24.jar:5.3.24] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateUsingFactoryMethod(AbstractAutowireCapableBeanFactory.java:1352) ~[spring-beans-5.3.24.jar:5.3.24] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1195) ~[spring-beans-5.3.24.jar:5.3.24] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:582) ~[spring-beans-5.3.24.jar:5.3.24] at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:542) ~[spring-beans-5.3.24.jar:5.3.24] at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335) ~[spring-beans-5.3.24.jar:5.3.24] at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234) ~[spring-beans-5.3.24.jar:5.3.24] at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333) ~[spring-beans-5.3.24.jar:5.3.24] at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:213) ~[spring-beans-5.3.24.jar:5.3.24] at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.getWebServerFactory(ServletWebServerApplicationContext.java:219) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.createWebServer(ServletWebServerApplicationContext.java:182) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.onRefresh(ServletWebServerApplicationContext.java:162) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:577) ~[spring-context-5.3.24.jar:5.3.24] at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:147) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:731) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:408) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.SpringApplication.run(SpringApplication.java:307) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.SpringApplication.run(SpringApplication.java:1303) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.SpringApplication.run(SpringApplication.java:1292) ~[spring-boot-2.7.6.jar:2.7.6] at io.github.bayang.jelu.JeluApplicationKt.main(JeluApplication.kt:20) ~[classes/:0.38.0] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Unknown Source) ~[na:na] at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49) ~[app/:na] at org.springframework.boot.loader.Launcher.launch(Launcher.java:108) ~[app/:na] at org.springframework.boot.loader.Launcher.launch(Launcher.java:58) ~[app/:na] at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:65) ~[app/:na] ```

2023-04-06 04:32:03.393 DEBUG 1 --- [main] o.apache.tomcat.util.compat.Jre19Compat : Class not found so assuming code is running on a pre-Java 19 JVM

Full log lines ``` 2023-04-06 04:32:03.393 DEBUG 1 --- [main] o.apache.tomcat.util.compat.Jre19Compat : Class not found so assuming code is running on a pre-Java 19 JVM java.lang.ClassNotFoundException: java.lang.WrongThreadException at java.base/java.net.URLClassLoader.findClass(Unknown Source) ~[na:na] at java.base/java.lang.ClassLoader.loadClass(Unknown Source) ~[na:na] at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:135) ~[app/:na] at java.base/java.lang.ClassLoader.loadClass(Unknown Source) ~[na:na] at java.base/java.lang.Class.forName0(Native Method) ~[na:na] at java.base/java.lang.Class.forName(Unknown Source) ~[na:na] at org.apache.tomcat.util.compat.Jre19Compat.(Jre19Compat.java:37) ~[tomcat-embed-core-9.0.69.jar:9.0.69] at org.apache.tomcat.util.compat.JreCompat.(JreCompat.java:72) ~[tomcat-embed-core-9.0.69.jar:9.0.69] at org.apache.catalina.startup.Tomcat.(Tomcat.java:1299) ~[tomcat-embed-core-9.0.69.jar:9.0.69] at org.springframework.boot.web.embedded.tomcat.TomcatServletWebServerFactory.getWebServer(TomcatServletWebServerFactory.java:194) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.createWebServer(ServletWebServerApplicationContext.java:184) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.onRefresh(ServletWebServerApplicationContext.java:162) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:577) ~[spring-context-5.3.24.jar:5.3.24] at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:147) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:731) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:408) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.SpringApplication.run(SpringApplication.java:307) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.SpringApplication.run(SpringApplication.java:1303) ~[spring-boot-2.7.6.jar:2.7.6] at org.springframework.boot.SpringApplication.run(SpringApplication.java:1292) ~[spring-boot-2.7.6.jar:2.7.6] at io.github.bayang.jelu.JeluApplicationKt.main(JeluApplication.kt:20) ~[classes/:0.38.0] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[na:na] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:na] at java.base/java.lang.reflect.Method.invoke(Unknown Source) ~[na:na] at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:49) ~[app/:na] at org.springframework.boot.loader.Launcher.launch(Launcher.java:108) ~[app/:na] at org.springframework.boot.loader.Launcher.launch(Launcher.java:58) ~[app/:na] at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:65) ~[app/:na] ```

Log lines when the HTTP 400 is triggered

2023-04-06 04:51:27.907 DEBUG 1 --- [http-nio-8400-Acceptor] o.apache.tomcat.util.threads.LimitLatch  : Counting up[http-nio-8400-Acceptor] latch=1
2023-04-06 04:51:27.909 DEBUG 1 --- [http-nio-8400-exec-4] o.a.tomcat.util.net.SocketWrapperBase    : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@4672a6ee:org.apache.tomcat.util.net.NioChannel@1ff243e5:java.nio.channels.SocketChannel[connected local=/172.21.0.5:8400 remote=/172.21.0.4:55770]], Read from buffer: [0]
2023-04-06 04:51:27.910 DEBUG 1 --- [http-nio-8400-exec-4] org.apache.tomcat.util.net.NioEndpoint   : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@4672a6ee:org.apache.tomcat.util.net.NioChannel@1ff243e5:java.nio.channels.SocketChannel[connected local=/172.21.0.5:8400 remote=/172.21.0.4:55770]], Read direct from socket: [935]
2023-04-06 04:51:27.915 DEBUG 1 --- [http-nio-8400-exec-4] o.apache.tomcat.util.threads.LimitLatch  : Counting down[http-nio-8400-exec-4] latch=1
2023-04-06 04:51:27.915 DEBUG 1 --- [http-nio-8400-exec-4] org.apache.tomcat.util.net.NioEndpoint   : Calling [org.apache.tomcat.util.net.NioEndpoint@17c001a3].closeSocket([org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@4672a6ee:org.apache.tomcat.util.net.NioChannel@1ff243e5:java.nio.channels.SocketChannel[connected local=/172.21.0.5:8400 remote=/172.21.0.4:55770]])

Which doesn't give me a sense of what the issue is.

I also disabled Authelia in SWAG and tested. Comparing what the request is that arrives in the docker container the only differences when Authelia is disabled is that these headers are now not present (which makes sense)

And this new header is present

"if-none-match": "W/\"5c2-sOYCy+nQ9kwC/VoHDW9ESPxN6AA\"",

But, disabling Authelia doesn't solve the problem. With the request passing through SWAG without any authentication still triggers the 400 in Tomcat.

I'll try bypassing SWAG and comparing how the requests appear (direct vs proxied) to see if I can identify what it is about the request coming through SWAG that causes Tomcat to reject it.

bayang commented 1 year ago

Ok, the tomcat debug logs are not relevant.

Can you make sure that your proxy tries to reach jelu through http and not https ?

gene1wood commented 2 weeks ago

Yes I've confirmed that the proxy (swag) is using http

        set $upstream_proto http;

I wasn't ever able to get this working and wasn't able to get any greater logging information than what I mentioned above.

bayang commented 2 weeks ago

that is weird, but my first guess is still one of the best options to explain why you are receiving a 400 and not another error.

Your first block of test in your first message, which is therequest received by jelu after the proxy if I understand correctly has this line : 

 "protocol": "https",

can you double check please ?