Why logs stop being useful in real systems

TL;DR: Basic logs work well for simple flows, but once concurrency, delays, and multiple users appear, they stop telling complete stories.

2025-10-19 22:55:56,577 INFO  demo.DemoApplication                             Starting DemoApplication using Java 24.0.1 with PID 188600 (/home/john-doe/Projects/demo/target/classes started by john_doe in /home/john-doe/Projects/demo)
2025-10-19 22:55:56,581 INFO  demo.DemoApplication                             No active profile set, falling back to 1 default profile: "default"
2025-10-19 22:55:57,198 INFO  o.s.boot.web.embedded.tomcat.TomcatWebServer     Tomcat initialized with port 8080 (http)
2025-10-19 22:55:57,204 INFO  org.apache.coyote.http11.Http11NioProtocol       Initializing ProtocolHandler ["http-nio-8080"]
2025-10-19 22:55:57,205 INFO  org.apache.catalina.core.StandardService         Starting service [Tomcat]
2025-10-19 22:55:57,205 INFO  org.apache.catalina.core.StandardEngine          Starting Servlet engine: [Apache Tomcat/10.1.46]
2025-10-19 22:55:57,223 INFO  o.a.c.c.ContainerBase.[Tomcat].[localhost].[/]   Initializing Spring embedded WebApplicationContext
2025-10-19 22:55:57,223 INFO  o.s.b.w.s.c.ServletWebServerApplicationContext   Root WebApplicationContext: initialization completed in 589 ms
2025-10-19 22:55:57,426 INFO  org.apache.coyote.http11.Http11NioProtocol       Starting ProtocolHandler ["http-nio-8080"]
2025-10-19 22:55:57,431 INFO  o.s.boot.web.embedded.tomcat.TomcatWebServer     Tomcat started on port 8080 (http) with context path '/'
2025-10-19 22:55:59,568 INFO  o.s.boot.web.embedded.tomcat.GracefulShutdown    Commencing graceful shutdown. Waiting for active requests to complete
2025-10-19 22:55:59,571 INFO  o.s.boot.web.embedded.tomcat.GracefulShutdown    Graceful shutdown complete

Thanks to the concept of logs, it’s easier to understand what’s going on in a working system – especially once problems start to appear.

The example above shows the start and shutdown of a Spring Framework service, a very common sight in Java enterprise applications. Logback is often used as the logging backend.

In this article, we’ll first look at logging in its most basic form, then gradually improve the configuration in our application. The end goal is simple: a solution that shortens the time required to understand what went wrong.

Although the examples focus on Logback, the ideas are not specific to it. Similar results can be achieved regardless of technology, programming language, or framework.

Understanding the basics

The core problem that logs should help solve is determining when and what exactly happened.

Let’s take a closer look at logs in their minimal configuration:

2025-10-18 16:02:35,338 INFO  demo.HelloPrinter    Hello world
2025-10-18 16:02:35,838 INFO  demo.HelloPrinter    How are you
2025-10-18 16:02:36,339 INFO  demo.HelloPrinter    Good bye
|                       |     |                    |
|                       |     |                    +--- the message
|                       |     |
|                       |     +--- class name
|                       |
|                       +--- log level
|
+--- timestamp

Chronological order is guaranteed in two ways.

First, the timestamp shows the order of events. Second, the log data structure itself only allows appending new entries, ensuring that reading logs top-to-bottom preserves sequence.

‘Log level’ distinguishes expected behaviour (DEBUG, INFO) from potential problems (WARN, ERROR). ‘Class name’ tells us where in the code the log was produced. ‘The message’ is a custom text prepared by the developer.

Let’s confirm that this matches the code:

package demo;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

@Component
public class HelloPrinter {

    private static final Logger logger = LoggerFactory.getLogger(HelloPrinter.class);

    public void print() {
        logger.info("Hello world");
        logger.info("How are you");
        logger.info("Good bye");
    }
}

So far, everything behaves exactly as expected.

Logback configuration (minimal but sufficient)

To produce logs formatted this way using Logback, the following configuration is used:

<configuration>

    <appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>
            %d{ISO8601} %highlight(%-5level) %yellow(%-48logger{48}) %msg %n%throwable
        </pattern>
        </encoder>
    </appender>

    <!-- root level="INFO" means I don't want to see DEBUG or TRACE.
         Without it at the Spring server start we would see a lot o DEBUG logs
         related to Spring Framework internals -->
    <root level="INFO">
        <appender-ref ref="Console"/>
    </root>

</configuration>

Key elements:

  • timestamp, 
  • log level (fixed width for readability), 
  • class / logger name, 
  • message, 
  • optional stack trace. 
%d{ISO8601} %-5level %-48logger{48} %msg %n%throwable
|           |        |              |    | |
|           |        |              |    | +--- pretty printed stack trace
|           |        |              |    |      …in case there was an exception
|           |        |              |    |
|           |        |              |    +--- new line to separate log line
|           |        |              |
|           |        |              +--- the message
|           |        |
|           |        +--- class name / logger
|           |             …points to a place in source code producing this log
|           |             …exactly 48 chars length, for easy reading
|           |
|           +--- log level
|                …exactly 5 chars length
|                …ERROR is 5 chars, but INFO is only 4
|                …and we want to keep consistency
|
+--- timestamp

This setup is clean, readable, and works well – until real life happens. 

❌ Problem: concurrent users blur the story

Now let’s look at a slightly more realistic scenario.

Three users modify orders at the same time. Quantity, item price, and total price are logged in different places:

2025-10-18 16:56:28,415 INFO  demo.PrintingDemo    Price of item = 15
2025-10-18 16:56:28,465 INFO  demo.PrintingDemo    Price of item = 36
2025-10-18 16:56:28,571 INFO  demo.PrintingDemo    Items in order = [1]
2025-10-18 16:56:28,581 INFO  demo.PrintingDemo    Price of item = 47
2025-10-18 16:56:28,611 INFO  demo.PrintingDemo    Items in order = [5]
2025-10-18 16:56:28,640 INFO  demo.PrintingDemo    Total price = 75
2025-10-18 16:56:28,714 INFO  demo.PrintingDemo    Total price = 36
2025-10-18 16:56:28,715 INFO  demo.PrintingDemo    Items in order = [3]
2025-10-18 16:56:28,746 INFO  demo.PrintingDemo    Total price = 141

At this point, the logs are no longer useful. We can’t tell:

  • which events belong to the same order,
  • whether totals are calculated correctly,
  • or which user triggered which sequence.

✅ Attempted solution: PID and thread ID

If you’re using Spring Boot (which defaults to Logback), the default configuration already includes:

  • a process ID (PID),
  • a thread ID.

Let’s make them explicit in the pattern:

%d{ISO8601} %-5level ${PID} [t=%thread] %-48logger{48} %msg %n%throwable
                     |      |
                     |      +--- thread id
                     |           …with small visual enhancement
                     |           …will look like this: [t=Thread-1]
                     |
                     +--- PID

PID helps distinguish:

  • different service instances,
  • restarts,
  • multi-instance deployments.

Thread ID helps show:

  • which requests are handled concurrently,
  • which execution paths run in parallel.

With this change, the same scenario becomes easier to follow:

2025-10-18 17:02:51,199 INFO  151993 [t=Thread-2] demo.PrintingDemo    Price of item = 63
2025-10-18 17:02:51,206 INFO  151993 [t=Thread-1] demo.PrintingDemo    Price of item = 34
2025-10-18 17:02:51,223 INFO  153222 [t=Thread-1] demo.PrintingDemo    Price of item = 58
2025-10-18 17:02:51,246 INFO  151993 [t=Thread-5] demo.PrintingDemo    Price of item = 94
2025-10-18 17:02:51,331 INFO  151993 [t=Thread-2] demo.PrintingDemo    Items in order = [1]
2025-10-18 17:02:51,354 INFO  151993 [t=Thread-2] demo.PrintingDemo    Total price = 63
2025-10-18 17:02:51,355 INFO  153222 [t=Thread-1] demo.PrintingDemo    Items in order = [4]
2025-10-18 17:02:51,355 INFO  151993 [t=Thread-4] demo.PrintingDemo    Price of item = 68
2025-10-18 17:02:51,358 INFO  151993 [t=Thread-5] demo.PrintingDemo    Items in order = [2]
2025-10-18 17:02:51,367 INFO  151993 [t=Thread-1] demo.PrintingDemo    Items in order = [2]
2025-10-18 17:02:51,371 INFO  151993 [t=Thread-1] demo.PrintingDemo    Total price = 68
2025-10-18 17:02:51,429 INFO  153222 [t=Thread-1] demo.PrintingDemo    Total price = 232
2025-10-18 17:02:51,456 INFO  151993 [t=Thread-5] demo.PrintingDemo    Total price = 188
2025-10-18 17:02:51,460 INFO  151993 [t=Thread-4] demo.PrintingDemo    Items in order = [5]
2025-10-18 17:02:51,629 INFO  151993 [t=Thread-4] demo.PrintingDemo    Total price = 340

Filtering by thread and PID, we can finally reconstruct a single order.

2025-10-18 17:02:51,206 INFO  151993 [t=Thread-1] demo.PrintingDemo    Price of item = 34
2025-10-18 17:02:51,367 INFO  151993 [t=Thread-1] demo.PrintingDemo    Items in order = [2]
2025-10-18 17:02:51,371 INFO  151993 [t=Thread-1] demo.PrintingDemo    Total price = 68

❌ Problem: time and scale break this approach

This solution only works when we know exactly when the problem happened.

In real systems:

  • users report issues hours later,
  • threads are reused,
  • hundreds of executions overlap.

Consider logs like this:

2025-10-19 18:29:53,428 INFO  169232 [t=Thread-2] demo.PrintingDemo    Price of item = 2
2025-10-19 18:29:53,467 INFO  169232 [t=Thread-3] demo.PrintingDemo    Price of item = 9
2025-10-19 18:29:53,484 INFO  169232 [t=Thread-1] demo.PrintingDemo    Price of item = 26
2025-10-19 18:29:53,493 INFO  169232 [t=Thread-2] demo.PrintingDemo    Items in order = [2]
2025-10-19 18:29:53,529 INFO  169232 [t=Thread-3] demo.PrintingDemo    Items in order = [5]
2025-10-19 18:29:53,545 INFO  169232 [t=Thread-1] demo.PrintingDemo    Items in order = [3]
2025-10-19 18:29:53,631 INFO  169232 [t=Thread-1] demo.PrintingDemo    Total price = 78
2025-10-19 18:29:53,645 INFO  169232 [t=Thread-2] demo.PrintingDemo    Total price = 4
2025-10-19 18:29:53,694 INFO  169232 [t=Thread-3] demo.PrintingDemo    Total price = 45
2025-10-19 18:29:53,720 INFO  169232 [t=Thread-1] demo.PrintingDemo    Price of item = 26
2025-10-19 18:29:53,797 INFO  169232 [t=Thread-3] demo.PrintingDemo    Price of item = 27
2025-10-19 18:29:53,801 INFO  169232 [t=Thread-2] demo.PrintingDemo    Price of item = 89
2025-10-19 18:29:53,847 INFO  169232 [t=Thread-2] demo.PrintingDemo    Items in order = [5]
2025-10-19 18:29:53,895 INFO  169232 [t=Thread-1] demo.PrintingDemo    Items in order = [2]
2025-10-19 18:29:53,919 INFO  169232 [t=Thread-1] demo.PrintingDemo    Total price = 52
2025-10-19 18:29:53,970 INFO  169232 [t=Thread-3] demo.PrintingDemo    Items in order = [2]
2025-10-19 18:29:53,990 INFO  169232 [t=Thread-2] demo.PrintingDemo    Total price = 445
2025-10-19 18:29:54,057 INFO  169232 [t=Thread-1] demo.PrintingDemo    Price of item = 47
2025-10-19 18:29:54,109 INFO  169232 [t=Thread-1] demo.PrintingDemo    Items in order = [4]
2025-10-19 18:29:54,163 INFO  169232 [t=Thread-3] demo.PrintingDemo    Total price = 54
2025-10-19 18:29:54,298 INFO  169232 [t=Thread-1] demo.PrintingDemo    Total price = 188

Even if we filter by thread ID = Thread-1…

2025-10-19 18:29:53,484 INFO  169232 [t=Thread-1] demo.PrintingDemo    Price of item = 26
2025-10-19 18:29:53,545 INFO  169232 [t=Thread-1] demo.PrintingDemo    Items in order = [3]
2025-10-19 18:29:53,631 INFO  169232 [t=Thread-1] demo.PrintingDemo    Total price = 78
2025-10-19 18:29:53,720 INFO  169232 [t=Thread-1] demo.PrintingDemo    Price of item = 26
2025-10-19 18:29:53,895 INFO  169232 [t=Thread-1] demo.PrintingDemo    Items in order = [2]
2025-10-19 18:29:53,919 INFO  169232 [t=Thread-1] demo.PrintingDemo    Total price = 52
2025-10-19 18:29:54,057 INFO  169232 [t=Thread-1] demo.PrintingDemo    Price of item = 47
2025-10-19 18:29:54,109 INFO  169232 [t=Thread-1] demo.PrintingDemo    Items in order = [4]
2025-10-19 18:29:54,298 INFO  169232 [t=Thread-1] demo.PrintingDemo    Total price = 188

The same thread now handles multiple, unrelated executions. Filtering by thread ID or PID now produces mixed stories.

At this point, trying to group logs effectively this way becomes tedious – which means we’re wasting valuable time.

Where this leaves us

At this stage, logs are technically correct, well formatted, and still incomplete. They describe events, but not executions. They tell us what happened – but not which story those events belonged to.

What comes next

Instead of squeezing more meaning out of threads and timestamp, we need logs to remember context.

In the next part, we’ll look at how to attach user context to logs without passing identifiers through every method:

→ Part 2: User context without breaking your design

And later, when users don’t exist and threads are not enough:

→ Part 3: Correlation IDs and end-to-end traceability

Let's talk

About the author

wiktor sztwiertnia

Wiktor Sztwiertnia

Senior Java Software Engineer