I’ve noticed some odd behavior with my SpringBoot micro service. I’m using spring mvc, springboot 3.3.3 and Java 21.
Consider the following code in a Controller (annotated with @RestController and lombok’s @Slf4j):
@GetMapping("/test/{id}")
public void getTest(@PathVariable Integer id) {
log.info("get test: {}", id);
}
@DeleteMapping("/test/{id}")
public void deleteTest(@PathVariable Integer id) throws InterruptedException {
TimeUnit.SECONDS.sleep(10);
log.info("delete test: {}", id);
}
@GetMapping("/test/{id}/something")
public void getTestSomething(@PathVariable Integer id) throws InterruptedException {
TimeUnit.SECONDS.sleep(10);
log.info("get test something: {}", id);
}
If I hit DELETE /test/3 followed by GET /test/3 within 10 seconds, the GET will wait until the DELETE request returns. However if I hit GET /test/3/something and then GET /test/3 it won’t wait. The latter is the behavior I would expect for both.
Also, if I do a different id for DELETE and the first GET, the GET won’t wait. For example, DELETE /test/4 followed by GET /test/3
Another interesting observation is that if I don’t use the passed in path variable, e.g. just don’t log it or pass it to anything, it won’t wait. The same goes if the paths don’t specify path variables and are equal. E.g: GET /test and DELETE /test
Also, if I include a @RequestParameter the waiting issue doesn’t occur. E.g. GET /test/3?key=value
Is the weird waiting behavior I’ve observed expected? Or have I uncovered some strange bug?
3
Project Tree
demo
├── pom.xml
├── src
│ └── main
│ ├── java
│ │ └── com
│ │ └── example
│ │ ├── DemoApplication.java
│ │ └── HelloController.java
│ └── resources
│ ├── application.properties
│ └── logback.xml
├── test1.sh
├── test2.sh
├── test3.sh
├── test4.sh
├── test5.sh
├── test6.sh
└── test-main.sh
pom.xml
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns="http://maven.apache.org/POM/4.0.0"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>3.3.3</version>
<relativePath/> <!-- lookup parent from repository -->
</parent>
<groupId>com.example</groupId>
<artifactId>demo</artifactId>
<version>0.0.1-SNAPSHOT</version>
<name>demo</name>
<description>Demo project for Spring Boot</description>
<properties>
<maven.compiler.source>17</maven.compiler.source>
<maven.compiler.target>17</maven.compiler.target>
<project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
<project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
</properties>
<dependencies>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-logging</artifactId>
</dependency>
<dependency>
<groupId>org.projectlombok</groupId>
<artifactId>lombok</artifactId>
</dependency>
</dependencies>
<build>
<finalName>app</finalName>
<plugins>
<plugin>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-maven-plugin</artifactId>
</plugin>
</plugins>
</build>
</project>
logback.xml
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d [%thread] %-5level %-50logger{40} - %msg%n</pattern>
</encoder>
</appender>
<appender name="RollingFile" class="ch.qos.logback.core.rolling.RollingFileAppender">
<file>app.log</file>
<encoder>
<pattern>%d [%thread] %-5level %-50logger{40} - %msg%n</pattern>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<fileNamePattern>app-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<maxFileSize>1MB</maxFileSize>
<maxHistory>30</maxHistory>
<totalSizeCap>10MB</totalSizeCap>
<cleanHistoryOnStart>true</cleanHistoryOnStart>
</rollingPolicy>
</appender>
<root level="INFO">
<appender-ref ref="Console" />
<appender-ref ref="RollingFile" />
</root>
</configuration>
DemoApplication.java
package com.example;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
@SpringBootApplication
public class DemoApplication {
public static void main(String[] args) {
SpringApplication.run(DemoApplication.class, args);
}
}
HelloController.java
I changed the return value of method to String and returned the corresponding date and time.
package com.example;
import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.*;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
import java.util.Calendar;
import java.util.concurrent.TimeUnit;
@Slf4j
@RestController
public class HelloController {
@GetMapping("/test/{id}")
public String getTest(@PathVariable Integer id) {
log.info("get test: {}", id);
LocalDateTime now = LocalDateTime.now();
DateTimeFormatter formatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS");
String formattedDateTime = now.format(formatter);
return formattedDateTime + "t" + "get test: "+ id + "n";
}
@DeleteMapping("/test/{id}")
public String deleteTest(@PathVariable Integer id) throws InterruptedException {
log.info("entry delete test: {}", id);
TimeUnit.SECONDS.sleep(10);
log.info("delete test: {}", id);
LocalDateTime now = LocalDateTime.now();
DateTimeFormatter formatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS");
String formattedDateTime = now.format(formatter);
return formattedDateTime + "t" + "delete test: "+ id + "n";
}
@GetMapping("/test/{id}/something")
public String getTestSomething(@PathVariable Integer id) throws InterruptedException {
log.info("entry get test something: {}", id);
TimeUnit.SECONDS.sleep(10);
log.info("get test something: {}", id);
LocalDateTime now = LocalDateTime.now();
DateTimeFormatter formatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS");
String formattedDateTime = now.format(formatter);
return formattedDateTime + "t" + "get test something: "+ id +"n";
}
}
Test Shell Script
-
test-main.sh call test1.sh, test2.sh, test3.sh, test4.sh, test5.sh, test6.sh
-
test1.sh (test4.sh) call
getTest -
test2.sh (test5.sh) call
deleteTest -
test3.sh (test6.sh) call
getTestSomething
test-main.sh
#!/bin/bash
echo "TEST MAIN START"
start_time0=$(date +%s)
for i in {1..6}; do
./test${i}.sh &
done
wait
end_time0=$(date +%s)
elapsed_time0=$((end_time0 - start_time0))
echo "TEST MAIN - Elapsed time: $elapsed_time0 seconds"
test1.sh
#!/bin/bash
echo "TEST 1 START"
start_time1=$(date +%s)
for i in {1..100}; do
curl -X GET "http://localhost:8080/test/${i}" &
done
wait
end_time1=$(date +%s)
elapsed_time1=$((end_time1 - start_time1))
echo "TEST 1 - Elapsed time: $elapsed_time1 seconds"
test2.sh
#!/bin/bash
echo "TEST 2 START"
start_time2=$(date +%s)
for i in {1..100}; do
curl -X DELETE "http://localhost:8080/test/${i}" &
done
wait
end_time2=$(date +%s)
elapsed_time2=$((end_time2 - start_time2))
echo "TEST 2 - Elapsed time: $elapsed_time2 seconds"
test3.sh
#!/bin/bash
echo "TEST 3 START"
start_time3=$(date +%s)
for i in {1..100}; do
curl -X GET "http://localhost:8080/test/${i}/something" &
done
wait
end_time3=$(date +%s)
elapsed_time3=$((end_time3 - start_time3))
echo "TEST 3 - Elapsed time: $elapsed_time3 seconds"
test4.sh
#!/bin/bash
echo "TEST 4 START"
start_time4=$(date +%s)
for i in {1..100}; do
curl -X GET "http://localhost:8080/test/${i}" &
done
wait
end_time4=$(date +%s)
elapsed_time4=$((end_time4 - start_time4))
echo "TEST 4 - Elapsed time: $elapsed_time4 seconds"
test5.sh
#!/bin/bash
echo "TEST 5 START"
start_time5=$(date +%s)
for i in {1..100}; do
curl -X DELETE "http://localhost:8080/test/${i}" &
done
wait
end_time5=$(date +%s)
elapsed_time5=$((end_time5 - start_time5))
echo "TEST 5 - Elapsed time: $elapsed_time5 seconds"
test6.sh
#!/bin/bash
echo "TEST 6 START"
start_time6=$(date +%s)
for i in {1..100}; do
curl -X GET "http://localhost:8080/test/${i}/something" &
done
wait
end_time6=$(date +%s)
elapsed_time6=$((end_time6 - start_time6))
echo "TEST 6 - Elapsed time: $elapsed_time6 seconds"
Build
mvn clean package
Run
java -jar target/app.jar
Run Test
test-main.sh
Result
You can count,
-
getTestpasses in the parameter id from 1 to 100, and each number is called 2 times (test1.sh, test4.sh) -
deleteTestpasses in the parameter id from 1 to 100, and each number is called 2 times (test2.sh, test5.sh) -
getTestSomethingpasses in the parameter id from 1 to 100, and each number is called 2 times (test3.sh, test6.sh)
TEST MAIN START
TEST 3 START
TEST 2 START
TEST 1 START
TEST 4 START
TEST 5 START
TEST 6 START
2024-09-26 20:05:44.372 get test: 67
2024-09-26 20:05:44.371 get test: 100
2024-09-26 20:05:44.345 get test: 90
2024-09-26 20:05:44.371 get test: 42
...
2024-09-26 20:05:44.762 get test: 76
2024-09-26 20:05:44.765 get test: 41
2024-09-26 20:05:44.769 get test: 31
2024-09-26 20:05:54.344 delete test: 72
2024-09-26 20:05:54.344 delete test: 46
2024-09-26 20:05:54.346 get test something: 43
2024-09-26 20:05:54.346 delete test: 77
2024-09-26 20:05:54.344 delete test: 1
...
2024-09-26 20:06:04.763 delete test: 19
2024-09-26 20:06:04.765 get test something: 27
2024-09-26 20:06:04.765 get test something: 29
2024-09-26 20:06:04.765 delete test: 25
2024-09-26 20:06:04.764 get test something: 95
TEST 5 - Elapsed time: 21 seconds
TEST 6 - Elapsed time: 21 seconds
TEST 2 - Elapsed time: 21 seconds
2024-09-26 20:06:04.780 get test something: 3
TEST 3 - Elapsed time: 21 seconds
TEST MAIN - Elapsed time: 21 seconds
app.log
You can check the http-nio-8080-exec-XX in app.log like http-nio-8080-exec-36 to see the processed Thread.
...
2024-09-26 20:05:44,340 [http-nio-8080-exec-36] INFO com.example.HelloController - get test: 54
2024-09-26 20:05:44,342 [http-nio-8080-exec-47] INFO com.example.HelloController - entry delete test: 46
2024-09-26 20:05:44,342 [http-nio-8080-exec-12] INFO com.example.HelloController - entry delete test: 1
2024-09-26 20:05:44,342 [http-nio-8080-exec-51] INFO com.example.HelloController - entry delete test: 72
2024-09-26 20:05:44,343 [http-nio-8080-exec-46] INFO com.example.HelloController - get test: 64
2024-09-26 20:05:44,640 [http-nio-8080-exec-111] INFO com.example.HelloController - entry get test something: 94
2024-09-26 20:05:44,652 [http-nio-8080-exec-109] INFO com.example.HelloController - get test: 16
...
2024-09-26 20:05:44,728 [http-nio-8080-exec-174] INFO com.example.HelloController - entry get test something: 86
2024-09-26 20:05:44,728 [http-nio-8080-exec-168] INFO com.example.HelloController - get test: 21
2024-09-26 20:05:44,729 [http-nio-8080-exec-158] INFO com.example.HelloController - entry get test something: 44
2024-09-26 20:05:44,729 [http-nio-8080-exec-165] INFO com.example.HelloController - entry delete test: 88
2024-09-26 20:05:44,725 [http-nio-8080-exec-148] INFO com.example.HelloController - entry get test something: 41
2024-09-26 20:05:44,727 [http-nio-8080-exec-160] INFO com.example.HelloController - get test: 51
...
2024-09-26 20:05:54,638 [http-nio-8080-exec-107] INFO com.example.HelloController - entry delete test: 89
2024-09-26 20:05:54,640 [http-nio-8080-exec-105] INFO com.example.HelloController - get test something: 93
2024-09-26 20:05:54,642 [http-nio-8080-exec-111] INFO com.example.HelloController - get test something: 94
2024-09-26 20:05:54,643 [http-nio-8080-exec-104] INFO com.example.HelloController - get test: 58
...
2024-09-26 20:05:54,707 [http-nio-8080-exec-139] INFO com.example.HelloController - delete test: 46
2024-09-26 20:05:54,708 [http-nio-8080-exec-153] INFO com.example.HelloController - get test: 47
2024-09-26 20:05:54,709 [http-nio-8080-exec-124] INFO com.example.HelloController - entry delete test: 57
2024-09-26 20:05:54,692 [http-nio-8080-exec-130] INFO com.example.HelloController - delete test: 97
2024-09-26 20:05:54,692 [http-nio-8080-exec-141] INFO com.example.HelloController - get test something: 83
2024-09-26 20:05:54,693 [http-nio-8080-exec-122] INFO com.example.HelloController - get test something: 100
2024-09-26 20:05:54,693 [http-nio-8080-exec-127] INFO com.example.HelloController - entry delete test: 26
2024-09-26 20:05:54,710 [http-nio-8080-exec-156] INFO com.example.HelloController - get test something: 90
2024-09-26 20:05:54,710 [http-nio-8080-exec-153] INFO com.example.HelloController - entry get test something: 76
2024-09-26 20:05:54,711 [http-nio-8080-exec-162] INFO com.example.HelloController - delete test: 99
2024-09-26 20:05:54,712 [http-nio-8080-exec-156] INFO com.example.HelloController - get test: 49
2024-09-26 20:05:54,712 [http-nio-8080-exec-122] INFO com.example.HelloController - entry delete test: 43
2024-09-26 20:05:54,712 [http-nio-8080-exec-162] INFO com.example.HelloController - get test: 9
2024-09-26 20:05:54,693 [http-nio-8080-exec-136] INFO com.example.HelloController - get test something: 42
2024-09-26 20:05:54,693 [http-nio-8080-exec-116] INFO com.example.HelloController - entry delete test: 64
2024-09-26 20:05:54,693 [http-nio-8080-exec-123] INFO com.example.HelloController - delete test: 12
2024-09-26 20:05:54,713 [http-nio-8080-exec-147] INFO com.example.HelloController - get test something: 64
...
2024-09-26 20:05:54,724 [http-nio-8080-exec-138] INFO com.example.HelloController - entry get test something: 28
2024-09-26 20:05:54,724 [http-nio-8080-exec-166] INFO com.example.HelloController - entry delete test: 86
2024-09-26 20:05:54,695 [http-nio-8080-exec-144] INFO com.example.HelloController - get test something: 30
2024-09-26 20:05:54,696 [http-nio-8080-exec-143] INFO com.example.HelloController - delete test: 48
2024-09-26 20:05:54,697 [http-nio-8080-exec-149] INFO com.example.HelloController - delete test: 17
2024-09-26 20:05:54,726 [http-nio-8080-exec-170] INFO com.example.HelloController - get test something: 85
2024-09-26 20:05:54,727 [http-nio-8080-exec-146] INFO com.example.HelloController - get test something: 50
2024-09-26 20:05:54,727 [http-nio-8080-exec-149] INFO com.example.HelloController - get test: 36
2024-09-26 20:05:54,697 [http-nio-8080-exec-135] INFO com.example.HelloController - get test something: 18
2024-09-26 20:05:54,728 [http-nio-8080-exec-170] INFO com.example.HelloController - get test: 97
2024-09-26 20:05:54,728 [http-nio-8080-exec-173] INFO com.example.HelloController - delete test: 74
2024-09-26 20:05:54,728 [http-nio-8080-exec-159] INFO com.example.HelloController - delete test: 75
2024-09-26 20:05:54,729 [http-nio-8080-exec-142] INFO com.example.HelloController - entry get test something: 71
2024-09-26 20:05:54,732 [http-nio-8080-exec-159] INFO com.example.HelloController - get test: 75
2024-09-26 20:05:54,732 [http-nio-8080-exec-143] INFO com.example.HelloController - entry delete test: 35
2024-09-26 20:05:54,732 [http-nio-8080-exec-135] INFO com.example.HelloController - entry get test something: 30
2024-09-26 20:05:54,697 [http-nio-8080-exec-114] INFO com.example.HelloController - get test: 46
2024-09-26 20:05:54,732 [http-nio-8080-exec-146] INFO com.example.HelloController - entry get test something: 16
2024-09-26 20:05:54,698 [http-nio-8080-exec-152] INFO com.example.HelloController - get test something: 4
2024-09-26 20:05:54,733 [http-nio-8080-exec-169] INFO com.example.HelloController - get test something: 93
2024-09-26 20:05:54,707 [http-nio-8080-exec-154] INFO com.example.HelloController - get test: 46
2024-09-26 20:05:54,734 [http-nio-8080-exec-114] INFO com.example.HelloController - get test: 81
2024-09-26 20:05:54,710 [http-nio-8080-exec-139] INFO com.example.HelloController - get test: 84
2024-09-26 20:05:54,735 [http-nio-8080-exec-168] INFO com.example.HelloController - get test something: 52
2024-09-26 20:05:54,712 [http-nio-8080-exec-141] INFO com.example.HelloController - entry get test something: 81
2024-09-26 20:05:54,735 [http-nio-8080-exec-114] INFO com.example.HelloController - entry get test something: 49
2024-09-26 20:05:54,735 [http-nio-8080-exec-176] INFO com.example.HelloController - get test something: 76
2024-09-26 20:05:54,735 [http-nio-8080-exec-177] INFO com.example.HelloController - delete test: 9
2024-09-26 20:05:54,735 [http-nio-8080-exec-139] INFO com.example.HelloController - get test: 57
2024-09-26 20:05:54,735 [http-nio-8080-exec-154] INFO com.example.HelloController - entry delete test: 69
2024-09-26 20:05:54,712 [http-nio-8080-exec-130] INFO com.example.HelloController - entry get test something: 97
2024-09-26 20:05:54,736 [http-nio-8080-exec-152] INFO com.example.HelloController - get test: 30
2024-09-26 20:05:54,736 [http-nio-8080-exec-155] INFO com.example.HelloController - delete test: 74
2024-09-26 20:05:54,736 [http-nio-8080-exec-151] INFO com.example.HelloController - get test something: 27
2024-09-26 20:05:54,737 [http-nio-8080-exec-176] INFO com.example.HelloController - get test: 62
2024-09-26 20:05:54,737 [http-nio-8080-exec-180] INFO com.example.HelloController - delete test: 71
2024-09-26 20:05:54,738 [http-nio-8080-exec-155] INFO com.example.HelloController - entry delete test: 87
2024-09-26 20:05:54,738 [http-nio-8080-exec-172] INFO com.example.HelloController - delete test: 87
2024-09-26 20:05:54,739 [http-nio-8080-exec-181] INFO com.example.HelloController - get test something: 6
2024-09-26 20:05:54,739 [http-nio-8080-exec-184] INFO com.example.HelloController - delete test: 65
2024-09-26 20:05:54,739 [http-nio-8080-exec-182] INFO com.example.HelloController - delete test: 70
2024-09-26 20:05:54,740 [http-nio-8080-exec-185] INFO com.example.HelloController - delete test: 53
2024-09-26 20:05:54,740 [http-nio-8080-exec-182] INFO com.example.HelloController - get test: 28
2024-09-26 20:05:54,741 [http-nio-8080-exec-178] INFO com.example.HelloController - delete test: 98
2024-09-26 20:05:54,741 [http-nio-8080-exec-188] INFO com.example.HelloController - delete test: 50
2024-09-26 20:05:54,742 [http-nio-8080-exec-163] INFO com.example.HelloController - delete test: 66
2024-09-26 20:05:54,742 [http-nio-8080-exec-151] INFO com.example.HelloController - entry get test something: 69
2024-09-26 20:05:54,742 [http-nio-8080-exec-182] INFO com.example.HelloController - entry get test something: 23
2024-09-26 20:05:54,742 [http-nio-8080-exec-180] INFO com.example.HelloController - get test: 49
2024-09-26 20:05:54,743 [http-nio-8080-exec-163] INFO com.example.HelloController - entry get test something: 68
2024-09-26 20:05:54,743 [http-nio-8080-exec-187] INFO com.example.HelloController - delete test: 82
2024-09-26 20:05:54,743 [http-nio-8080-exec-177] INFO com.example.HelloController - entry delete test: 62
2024-09-26 20:05:54,745 [http-nio-8080-exec-181] INFO com.example.HelloController - entry get test something: 34
2024-09-26 20:05:54,714 [http-nio-8080-exec-162] INFO com.example.HelloController - entry get test something: 67
2024-09-26 20:05:54,720 [http-nio-8080-exec-136] INFO com.example.HelloController - entry get test something: 72
2024-09-26 20:05:54,730 [http-nio-8080-exec-158] INFO com.example.HelloController - get test something: 44
2024-09-26 20:05:54,730 [http-nio-8080-exec-165] INFO com.example.HelloController - delete test: 88
2024-09-26 20:05:54,747 [http-nio-8080-exec-195] INFO com.example.HelloController - get test something: 17
2024-09-26 20:05:54,747 [http-nio-8080-exec-196] INFO com.example.HelloController - delete test: 68
2024-09-26 20:05:54,747 [http-nio-8080-exec-165] INFO com.example.HelloController - entry get test something: 48
2024-09-26 20:05:54,747 [http-nio-8080-exec-158] INFO com.example.HelloController - entry get test something: 86
2024-09-26 20:05:54,730 [http-nio-8080-exec-173] INFO com.example.HelloController - entry delete test: 33
2024-09-26 20:05:54,730 [http-nio-8080-exec-148] INFO com.example.HelloController - get test something: 41
2024-09-26 20:05:54,730 [http-nio-8080-exec-144] INFO com.example.HelloController - get test: 38
2024-09-26 20:05:54,748 [http-nio-8080-exec-195] INFO com.example.HelloController - entry get test something: 87
2024-09-26 20:05:54,749 [http-nio-8080-exec-148] INFO com.example.HelloController - entry delete test: 33
2024-09-26 20:05:54,749 [http-nio-8080-exec-196] INFO com.example.HelloController - get test: 43
2024-09-26 20:05:54,730 [http-nio-8080-exec-150] INFO com.example.HelloController - get test: 89
2024-09-26 20:05:54,730 [http-nio-8080-exec-170] INFO com.example.HelloController - entry get test something: 15
2024-09-26 20:05:54,724 [http-nio-8080-exec-132] INFO com.example.HelloController - entry get test something: 47
2024-09-26 20:05:54,731 [http-nio-8080-exec-161] INFO com.example.HelloController - delete test: 90
2024-09-26 20:05:54,751 [http-nio-8080-exec-196] INFO com.example.HelloController - get test: 70
2024-09-26 20:05:54,751 [http-nio-8080-exec-150] INFO com.example.HelloController - entry get test something: 19
2024-09-26 20:05:54,731 [http-nio-8080-exec-160] INFO com.example.HelloController - get test something: 53
2024-09-26 20:05:54,731 [http-nio-8080-exec-145] INFO com.example.HelloController - entry delete test: 58
2024-09-26 20:06:04,763 [http-nio-8080-exec-161] INFO com.example.HelloController - get test something: 27
2024-09-26 20:06:04,765 [http-nio-8080-exec-168] INFO com.example.HelloController - delete test: 25
2024-09-26 20:06:04,765 [http-nio-8080-exec-186] INFO com.example.HelloController - get test something: 29
2024-09-26 20:06:04,780 [http-nio-8080-exec-192] INFO com.example.HelloController - get test something: 3
I don’t see what’s wrong?