Java: Finding out the root cause of an unexpected log message
Tags: java, spring
Published: 2022-04-02 10:06:31

---
title: Java: Finding out the root cause of an unexpected log message
published: true
description: Debugging story for H2 database configuration in a Spring Boot app
tags: java, spring
---

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.

```text
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'
```

## 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:

```bash
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
```

## Search query

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

```text
$ 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
```

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](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/vhww0wk41hwz92xqs0xi.png)

## 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](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/kcje18m6oqi0gmzjr4r6.png)

## Solution

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

```java
@Configuration
class BffConfig {

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

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

```yml
spring:
  datasource:
    data: classpath:org/springframework/session/jdbc/schema-h2.sql
```

## References

- [Searching for a string on multiple zip files](https://unix.stackexchange.com/questions/18552/searching-for-a-string-on-multiple-zip-files) 
- [Spring Boot default H2 jdbc connection (and H2 console)](https://stackoverflow.com/a/32395375/2339010) 
- [Spring Boot - Loading Initial Data](https://stackoverflow.com/a/49257939/2339010)