DescartesResearch / TeaStore

A micro-service reference test application for model extraction, cloud management, energy efficiency, power prediction, single- and multi-tier auto-scaling
https://se.informatik.uni-wuerzburg.de
Apache License 2.0
118 stars 136 forks source link

How to get application-level logs (if any)? #220

Closed SoerenHenning closed 1 year ago

SoerenHenning commented 2 years ago

Hey folks,

we just started playing around with TeaStore and are trying to run it along with Open Service Mesh (OSM) in Kubernetes. While without OSM everything's working fine, we experience some connection errors with sidecars injected by OSM. For example, the status page indicates that some services could not be reached or service remain in a generating/waiting state forever. We are now trying to investigate this further, but it's a bit difficult to find the root cause.

Is TeaStore generating any log messages? Especially while setting up the persistence some information about errors would be helpful. If TeaStore does, where can we find those logs? $ kubectl logs -f teastore-persistence-... -c teastore-persistence only reports the default Tomcat logs.

SimonEismann commented 2 years ago

Hi Sören, we previously ran the TeaStore with the Istio service mesh, so in theory, this should be possible.

In general, this sounds like there might be some networking issues where pods can not communicate with the persistence or the persistence can not connect to the database container. My initial theory would be that the persistence can not reach the database as this would cause the recommender/imageprovider to stay in the generating/waiting state and the persistence to be unreachable. Since you are getting the generating/waiting state, this means that the pods can communicate with the registry so there seems to be some network connectivity.

You are already on the right track, that the next step would be to check the logs of the persistence container. Here, it's quite odd that only the tomcat logs show up. Could you post an example of what the persistence logs currently look like?

SoerenHenning commented 1 year ago

Hi Simon, sorry for the late reply. We got OSM working with some trial and error (and expert knowledge from @benediktwetzel). Specifying an appProtocol in the database service did trick. I will open a PR once everything's working as expected.

Getting back to my initial question, these are the logs from the persistence service:

$ kubectl logs -f teastore-persistence-d69d45b4-j2xkv -c teastore-persistence 
Total Host Memory = 16247264 KiB
Container CGroup Limit = 9007199254740988 KiB
NOTE: Picked up JDK_JAVA_OPTIONS:  --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.util=ALL-UNNAMED --add-opens=java.base/java.util.concurrent=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
02-Aug-2022 14:08:33.996 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name:   Apache Tomcat/10.0.7
02-Aug-2022 14:08:34.075 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Jun 8 2021 16:31:06 UTC
02-Aug-2022 14:08:34.112 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 10.0.7.0
02-Aug-2022 14:08:34.112 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
02-Aug-2022 14:08:34.112 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            5.4.0-122-generic
02-Aug-2022 14:08:34.113 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
02-Aug-2022 14:08:34.113 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/local/openjdk-11
02-Aug-2022 14:08:34.114 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           11.0.11+9
02-Aug-2022 14:08:34.114 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
02-Aug-2022 14:08:34.114 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /usr/local/tomcat
02-Aug-2022 14:08:34.115 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /usr/local/tomcat
02-Aug-2022 14:08:34.119 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
02-Aug-2022 14:08:34.123 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
02-Aug-2022 14:08:34.142 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.util=ALL-UNNAMED
02-Aug-2022 14:08:34.142 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.util.concurrent=ALL-UNNAMED
02-Aug-2022 14:08:34.142 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
02-Aug-2022 14:08:34.143 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties
02-Aug-2022 14:08:34.146 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
02-Aug-2022 14:08:34.146 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -javaagent:/kieker/agent/agent.jar
02-Aug-2022 14:08:34.147 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dkieker.monitoring.configuration=/kieker/config/kieker.monitoring.properties
02-Aug-2022 14:08:34.147 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Daj.weaving.verbose=false
02-Aug-2022 14:08:34.148 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.aspectj.weaver.loadtime.configuration=aop.xml
02-Aug-2022 14:08:34.148 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dkieker.monitoring.skipDefaultAOPConfiguration=true
02-Aug-2022 14:08:34.149 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Daj.weaving.loadersToSkip=java.net.URLClassLoader
02-Aug-2022 14:08:34.151 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcom.sun.jndi.ldap.object.disableEndpointIdentification=true
02-Aug-2022 14:08:34.151 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
02-Aug-2022 14:08:34.151 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
02-Aug-2022 14:08:34.152 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
02-Aug-2022 14:08:34.152 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
02-Aug-2022 14:08:34.152 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/usr/local/tomcat
02-Aug-2022 14:08:34.152 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/local/tomcat
02-Aug-2022 14:08:34.153 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/usr/local/tomcat/temp
02-Aug-2022 14:08:34.164 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded Apache Tomcat Native library [1.2.30] using APR version [1.6.5].
02-Aug-2022 14:08:34.164 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true], UDS [true].
02-Aug-2022 14:08:34.169 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized [OpenSSL 1.1.1d  10 Sep 2019]
02-Aug-2022 14:08:36.150 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
02-Aug-2022 14:08:36.262 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-nio-127.0.0.1-8009"]
02-Aug-2022 14:08:36.275 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [3040] milliseconds
02-Aug-2022 14:08:36.506 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
02-Aug-2022 14:08:36.509 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/10.0.7]
02-Aug-2022 14:08:36.593 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive [/usr/local/tomcat/webapps/tools.descartes.teastore.persistence.war]
02-Aug-2022 14:08:41.889 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
[EL Info]: 2022-08-02 14:08:46.14--ServerSession(904031493)--EclipseLink, version: Eclipse Persistence Services - 3.0.1.v202104070723

Looks like the SLF4J messages are the reason why no logs regarding the database connection are showing up.

SimonEismann commented 1 year ago

Hi Soeren, great to hear that you guys got it working with OSM 👍 A PR that adds compatibility with OSM would be much appreciated!

Regarding the logging issue, there are quite a few logs missing that should come up on every start of the persistence service. At first glance, it looks like you are correct and there is something wrong with our SLF4J logger that prevents logs from being written.

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.

My first assumption would be that we broke this when we did the version bump for many outdated dependencies. I'll validate whether the other services also do not provide any logs and look into fixing this sometime next week hopefully.

SimonEismann commented 1 year ago

After looking at this, I can currently not reproduce the issue. If I run a naked persistence container, I get quite noisy logs about it not being able to connect to the database. Could you maybe check if you can reproduce the issue with the missing logs by deploying only the persistence container?

On a side note, the SLF4J error message seems to be caused by our Kieker integration and is not related to application-level logs. I've reached out to the Kieker team on how to best address this.

Further, I've looked into what's causing the following warning and was able to get rid of it :)

NOTE: Picked up JDK_JAVA_OPTIONS:  --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.util=ALL-UNNAMED --add-opens=java.base/java.util.concurrent=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
SoerenHenning commented 1 year ago

When only starting the persistence pod, I'm getting the following logs (independent of whether I'm starting a Docker container or applying the Deployment with OSM installled.

$ kubectl logs -f teastore-persistence-5ffb6c946-zgkl8 teastore-persistence 
Total Host Memory = 16247264 KiB
Container CGroup Limit = 4096000 KiB
Setting heap space to 2048000 KiB
NOTE: Picked up JDK_JAVA_OPTIONS:  --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.base/java.util=ALL-UNNAMED --add-opens=java.base/java.util.concurrent=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
15-Aug-2022 12:08:21.489 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name:   Apache Tomcat/10.0.7
15-Aug-2022 12:08:21.494 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Jun 8 2021 16:31:06 UTC
15-Aug-2022 12:08:21.494 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 10.0.7.0
15-Aug-2022 12:08:21.494 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
15-Aug-2022 12:08:21.494 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            5.4.0-122-generic
15-Aug-2022 12:08:21.494 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
15-Aug-2022 12:08:21.495 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/local/openjdk-11
15-Aug-2022 12:08:21.495 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           11.0.11+9
15-Aug-2022 12:08:21.495 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
15-Aug-2022 12:08:21.495 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /usr/local/tomcat
15-Aug-2022 12:08:21.495 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /usr/local/tomcat
15-Aug-2022 12:08:21.519 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
15-Aug-2022 12:08:21.519 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
15-Aug-2022 12:08:21.519 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.util=ALL-UNNAMED
15-Aug-2022 12:08:21.520 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.util.concurrent=ALL-UNNAMED
15-Aug-2022 12:08:21.520 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
15-Aug-2022 12:08:21.520 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties
15-Aug-2022 12:08:21.520 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
15-Aug-2022 12:08:21.520 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -javaagent:/kieker/agent/agent.jar
15-Aug-2022 12:08:21.520 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dkieker.monitoring.configuration=/kieker/config/kieker.monitoring.properties
15-Aug-2022 12:08:21.520 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Daj.weaving.verbose=false
15-Aug-2022 12:08:21.520 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.aspectj.weaver.loadtime.configuration=aop.xml
15-Aug-2022 12:08:21.521 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dkieker.monitoring.skipDefaultAOPConfiguration=true
15-Aug-2022 12:08:21.521 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Daj.weaving.loadersToSkip=java.net.URLClassLoader
15-Aug-2022 12:08:21.521 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcom.sun.jndi.ldap.object.disableEndpointIdentification=true
15-Aug-2022 12:08:21.521 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
15-Aug-2022 12:08:21.521 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
15-Aug-2022 12:08:21.521 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
15-Aug-2022 12:08:21.521 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
15-Aug-2022 12:08:21.521 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/usr/local/tomcat
15-Aug-2022 12:08:21.521 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/local/tomcat
15-Aug-2022 12:08:21.521 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/usr/local/tomcat/temp
15-Aug-2022 12:08:21.542 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded Apache Tomcat Native library [1.2.30] using APR version [1.6.5].
15-Aug-2022 12:08:21.542 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true], UDS [true].
15-Aug-2022 12:08:21.556 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized [OpenSSL 1.1.1d  10 Sep 2019]
15-Aug-2022 12:08:21.968 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
15-Aug-2022 12:08:22.007 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-nio-127.0.0.1-8009"]
15-Aug-2022 12:08:22.008 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [767] milliseconds
15-Aug-2022 12:08:22.073 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
15-Aug-2022 12:08:22.074 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/10.0.7]
15-Aug-2022 12:08:22.094 INFO [main] org.apache.catalina.startup.HostConfig.deployWAR Deploying web application archive [/usr/local/tomcat/webapps/tools.descartes.teastore.persistence.war]
15-Aug-2022 12:08:23.364 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
[EL Info]: 2022-08-15 12:08:24.744--ServerSession(1104938392)--EclipseLink, version: Eclipse Persistence Services - 3.0.1.v202104070723
[EL Severe]: ejb: 2022-08-15 12:08:24.931--ServerSession(1104938392)--Exception [EclipseLink-4002] (Eclipse Persistence Services - 3.0.1.v202104070723): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Error Code: 0
[EL Info]: 2022-08-15 12:08:26.932--ServerSession(1104938392)--EclipseLink, version: Eclipse Persistence Services - 3.0.1.v202104070723
[EL Severe]: ejb: 2022-08-15 12:08:26.935--ServerSession(1104938392)--Exception [EclipseLink-4002] (Eclipse Persistence Services - 3.0.1.v202104070723): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Error Code: 0
[EL Info]: 2022-08-15 12:08:28.936--ServerSession(1104938392)--EclipseLink, version: Eclipse Persistence Services - 3.0.1.v202104070723
[EL Severe]: ejb: 2022-08-15 12:08:28.938--ServerSession(1104938392)--Exception [EclipseLink-4002] (Eclipse Persistence Services - 3.0.1.v202104070723): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Error Code: 0
[EL Info]: 2022-08-15 12:08:30.939--ServerSession(1104938392)--EclipseLink, version: Eclipse Persistence Services - 3.0.1.v202104070723
[EL Severe]: ejb: 2022-08-15 12:08:30.942--ServerSession(1104938392)--Exception [EclipseLink-4002] (Eclipse Persistence Services - 3.0.1.v202104070723): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Error Code: 0
[EL Info]: 2022-08-15 12:08:32.943--ServerSession(1104938392)--EclipseLink, version: Eclipse Persistence Services - 3.0.1.v202104070723
[EL Severe]: ejb: 2022-08-15 12:08:32.945--ServerSession(1104938392)--Exception [EclipseLink-4002] (Eclipse Persistence Services - 3.0.1.v202104070723): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Error Code: 0
[EL Info]: 2022-08-15 12:08:34.946--ServerSession(1104938392)--EclipseLink, version: Eclipse Persistence Services - 3.0.1.v202104070723
[EL Severe]: ejb: 2022-08-15 12:08:34.95--ServerSession(1104938392)--Exception [EclipseLink-4002] (Eclipse Persistence Services - 3.0.1.v202104070723): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Error Code: 0
[EL Info]: 2022-08-15 12:08:36.951--ServerSession(1104938392)--EclipseLink, version: Eclipse Persistence Services - 3.0.1.v202104070723
[EL Severe]: ejb: 2022-08-15 12:08:36.953--ServerSession(1104938392)--Exception [EclipseLink-4002] (Eclipse Persistence Services - 3.0.1.v202104070723): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Error Code: 0
[EL Info]: 2022-08-15 12:08:38.953--ServerSession(1104938392)--EclipseLink, version: Eclipse Persistence Services - 3.0.1.v202104070723
[EL Severe]: ejb: 2022-08-15 12:08:38.956--ServerSession(1104938392)--Exception [EclipseLink-4002] (Eclipse Persistence Services - 3.0.1.v202104070723): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Error Code: 0
[EL Info]: 2022-08-15 12:08:40.957--ServerSession(1104938392)--EclipseLink, version: Eclipse Persistence Services - 3.0.1.v202104070723
[EL Severe]: ejb: 2022-08-15 12:08:40.959--ServerSession(1104938392)--Exception [EclipseLink-4002] (Eclipse Persistence Services - 3.0.1.v202104070723): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Error Code: 0
[EL Info]: 2022-08-15 12:08:42.96--ServerSession(1104938392)--EclipseLink, version: Eclipse Persistence Services - 3.0.1.v202104070723
[EL Severe]: ejb: 2022-08-15 12:08:42.962--ServerSession(1104938392)--Exception [EclipseLink-4002] (Eclipse Persistence Services - 3.0.1.v202104070723): org.eclipse.persistence.exceptions.DatabaseException
Internal Exception: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
Error Code: 0

But these logs don't seem to be application-level, are they? For example, I would expect to see logs such as those: https://github.com/DescartesResearch/TeaStore/blob/f1cc567227e65b0e682b47dd6e76218d1fb1a981/services/tools.descartes.teastore.persistence/src/main/java/tools/descartes/teastore/persistence/daemons/InitialDataGenerationDaemon.java#L68 (Correct me if I'm wrong, I didn't looked into the TeaStore call graphs in detail and was only expecting to see such logs.)

SimonEismann commented 1 year ago

Alright, after looking into this, it seems like it was the SLF4J warning after all :) Adding Kieker as a dependency caused slf4j to be initialized earlier than expected when the logging implementation is not available on the classpath yet.

I've pushed some changes on the dev branch to hopefully fix this. Could you test if using the newest containers with the :development tag resolves the issue? Then I could push out a new release that contains this fix, as the missing logging fix is something that we should get into the main branch asap :)

SoerenHenning commented 1 year ago

Great, logs are working now! :)

SimonEismann commented 1 year ago

Version 1.4.2 with the fix is now on dockerhub :)