DEV Community

Jan Mewes
Jan Mewes

Posted on

Java: Finding out the root cause of an unexpected log message

Imagine, you are developing a Java/Spring app. You are correctly following a tutorial for configuring a database. But it doesn't work as expected. There is a log message which gives a hint about the root cause, but you don't know from where exactly it is coming. This blog post explores how the hint in this error message can be leveraged to fix the underlying problem.

Example

Even though the datasource configuration has been configured with the URL jdbc:h2:mem:ksch, still the default URL jdbc:h2:mem:testdb is being used.

2022-04-02 09:53:26.037  INFO 27600 --- [           main] o.s.j.d.e.EmbeddedDatabaseFactory        :
Starting embedded database: url='jdbc:h2:mem:testdb;DB_CLOSE_DELAY=-1;DB_CLOSE_ON_EXIT=false', username='sa'
Enter fullscreen mode Exit fullscreen mode

JAR search

It would be great if there would be a tool to search for the log message over all the JAR files in the Maven caches. And it turns out there is a tool that can do that:

https://github.com/Genivia/ugrep

Installation

ugrep can be used across a wide range of operating systems. However, there is no Ubuntu package available. But the project's Dockerfile is based on Ubuntu. So, from there we can get the steps required to compile the tool manually:

sudo apt-get install -y \
  nmake \
  vim \
  git \
  clang \
  wget \
  unzip \
  libpcre2-dev \
  libz-dev \
  libbz2-dev \
  liblzma-dev \
  liblz4-dev \
  libzstd-dev \
git clone https://github.com/Genivia/ugrep
cd ugrep/
./build.sh
sudo make install
Enter fullscreen mode Exit fullscreen mode

Search query

Now we can search for the suspicious log message in the Maven caches which contain all of the project's dependencies.

$ cd ~/.m2/repository/
$ ugrep -z "Starting embedded database"
Binary file org/springframework/spring-jdbc/5.2.7.RELEASE/spring-jdbc-5.2.7.RELEASE.jar{org/springframework/jdbc/datasource/embedded/EmbeddedDatabaseFactory.class} matches
Enter fullscreen mode Exit fullscreen mode

So, it is coming from the "spring-jdbc" project and we can search there for the file and line from where the log message originates:

https://github.dev/spring-projects/spring-framework/tree/971f665eb1e8cd9e8a0c788a8f5612f815894082/spring-jdbc

Disclaimer: If you look closely at the name of the logger in the original log message, you might be faster to find the right source file to introspect. But that is too easy, isn't it?

File finder

Debug

After having found the log message in the source code, we can set a breakpoint and start the app in debug mode. By following the data flow with further browsing in the IDE, we can logically deduce the root cause of the problem.

Debugger

Solution

In this case, it turned out that the root cause was a custom datasource which canceled out the auto-configuration:

@Configuration
class BffConfig {

    @Bean
    public EmbeddedDatabase dataSource() {
        return new EmbeddedDatabaseBuilder()
            .setType(EmbeddedDatabaseType.H2).addScript("org/springframework/session/jdbc/schema-h2.sql").build();
    }
}
Enter fullscreen mode Exit fullscreen mode

The solution was delete the custom datasource builder and move the init script into the profile configuration:

spring:
  datasource:
    data: classpath:org/springframework/session/jdbc/schema-h2.sql
Enter fullscreen mode Exit fullscreen mode

References

Top comments (0)