Hello!
I've run into the following problem. When a request (which is forwarding to a local endpoint) gets processed in a post zuul filter for a long time, other requests get blocked till the 1st one finishes. But if on the contrary, if a non-forwarding request is processed for a long time in a post zuul filter, other requests don't wait and finish before the 1st one. I wanted to know why is this behaviour happening, I've been debugging but still can't find the reason.
Here's the simplified example:
I have a SampleGateway application: https://github.com/yalexeyenko/SampleGateway build.gradle:
plugins {
id 'org.springframework.boot' version '2.5.5'
id 'io.spring.dependency-management' version '1.0.11.RELEASE'
id 'java'
}
group = 'com.example'
version = '0.0.1-SNAPSHOT'
sourceCompatibility = '11'
configurations {
compileOnly {
extendsFrom annotationProcessor
}
}
repositories {
mavenCentral()
}
dependencyManagement {
imports {
mavenBom "org.springframework.cloud:spring-cloud-starter-parent:Hoxton.SR10"
}
}
dependencies {
implementation 'org.springframework.boot:spring-boot-starter-web'
compileOnly 'org.projectlombok:lombok'
annotationProcessor 'org.projectlombok:lombok'
testImplementation 'org.springframework.boot:spring-boot-starter-test'
//
implementation 'org.springframework.boot:spring-boot-starter'
implementation 'org.springframework.cloud:spring-cloud-starter-netflix-zuul:2.2.9.RELEASE'
}
test {
useJUnitPlatform()
}
application.yml:
zuul:
routes:
greeting:
path: /greeting
service-id: forward:/
goodbye:
path: /goodbye/**
url: http://localhost:8080/goodbye
seeya:
path: /seeya/**
url: http://localhost:8080/seeya
server:
port: 9002
SampleGatewayApplication:
@EnableZuulProxy
@SpringBootApplication
public class SampleGatewayApplication {
public static void main(String[] args) {
SpringApplication.run(SampleGatewayApplication.class, args);
}
}
CustomPostFilter:
@Component
public class CustomPostFilter extends ZuulFilter {
private static final Logger LOGGER = LoggerFactory.getLogger(CustomPostFilter.class);
@Override
public String filterType() {
return FilterConstants.POST_TYPE;
}
@Override
public int filterOrder() {
return 2;
}
@Override
public boolean shouldFilter() {
var context = RequestContext.getCurrentContext();
var request = context.getRequest();
var uri = request.getRequestURI();
return !uri.equals("/seeya");
}
@SneakyThrows
@Override
public Object run() {
var context = RequestContext.getCurrentContext();
var request = context.getRequest();
var shouldWait = request.getHeader("should_wait");
var uri = request.getRequestURI();
var correlationId = request.getHeader("correlation_id");
LOGGER.info("Request '{}' [{}] entered CustomPostFilter", uri, correlationId);
if (shouldWait.equals("YES")) {
LOGGER.info("Request '{}' [{}] is waiting on CustomPostFilter", uri, correlationId);
Thread.sleep(20000);
LOGGER.info("Request '{}' [{}] is released on CustomPostFilter", uri, correlationId);
}
LOGGER.info("Request '{}' [{}] leaves CustomPostFilter", uri, correlationId);
return null;
}
}
GreetingRetrieveController:
@Controller
@RequestMapping("/greeting")
public class GreetingRetrieveController {
@GetMapping
public ResponseEntity<String> getGreeting() {
return ResponseEntity.ok("Hi there!");
}
}
And I gave a SampleService application: https://github.com/yalexeyenko/SampleService bulid.gradle:
plugins {
id 'org.springframework.boot' version '2.5.5'
id 'io.spring.dependency-management' version '1.0.11.RELEASE'
id 'java'
}
group = 'com.example'
version = '0.0.1-SNAPSHOT'
sourceCompatibility = '11'
configurations {
compileOnly {
extendsFrom annotationProcessor
}
}
repositories {
mavenCentral()
}
dependencies {
implementation 'org.springframework.boot:spring-boot-starter-web'
compileOnly 'org.projectlombok:lombok'
annotationProcessor 'org.projectlombok:lombok'
testImplementation 'org.springframework.boot:spring-boot-starter-test'
}
test {
useJUnitPlatform()
}
SampleServiceApplication:
@SpringBootApplication
public class SampleServiceApplication {
public static void main(String[] args) {
SpringApplication.run(SampleServiceApplication.class, args);
}
}
SampleController:
@Controller
public class SampleController {
@GetMapping("/goodbye")
public ResponseEntity<String> getGoodBye() {
return ResponseEntity.ok("Good Bye!");
}
@GetMapping("/seeya")
public ResponseEntity<String> getSeeYa() {
return ResponseEntity.ok("See ya!");
}
}
I emulate long-running requests by adding "should_wait" header with value YES/NO. Postman collection with the requests: https://www.getpostman.com/collections/0500fbbaec963fa39ef8
I've run the following cases:
Case 1: 1. GET localhost:9002/greeting WAIT (forwards to a local controller. Delay is emulated by Thread.sleep(20000) in CustomPostFilter) wait a few seconds 2. GET localhost:9002/greeting FAST
Result: 2nd request waits till the 1st one finishes
Logs:
2021-10-03 13:17:19.460 INFO 30184 --- [nio-9002-exec-9] c.e.samplegateway.CustomPostFilter : Request '//greeting' [1] entered CustomPostFilter
2021-10-03 13:17:19.460 INFO 30184 --- [nio-9002-exec-9] c.e.samplegateway.CustomPostFilter : Request '//greeting' [1] is waiting on CustomPostFilter
2021-10-03 13:17:39.460 INFO 30184 --- [nio-9002-exec-9] c.e.samplegateway.CustomPostFilter : Request '//greeting' [1] is released on CustomPostFilter
2021-10-03 13:17:39.460 INFO 30184 --- [nio-9002-exec-9] c.e.samplegateway.CustomPostFilter : Request '//greeting' [1] leaves CustomPostFilter
2021-10-03 13:17:39.464 INFO 30184 --- [nio-9002-exec-9] c.e.samplegateway.CustomPostFilter : Request '//greeting' [2] entered CustomPostFilter
2021-10-03 13:17:39.464 INFO 30184 --- [nio-9002-exec-9] c.e.samplegateway.CustomPostFilter : Request '//greeting' [2] leaves CustomPostFilter
Case 2: 1. GET localhost:9002/greeting WAIT (forwards to a local controller. Delay is emulated by Thread.sleep(20000) in CustomPostFilter) wait a few seconds 2. GET localhost:9002/goodbye FAST (routes to another service)
Result: 2nd request waits till the 1st one finishes
Logs:
2021-10-03 13:21:54.429 INFO 30184 --- [io-9002-exec-10] c.e.samplegateway.CustomPostFilter : Request '//greeting' [1] entered CustomPostFilter
2021-10-03 13:21:54.429 INFO 30184 --- [io-9002-exec-10] c.e.samplegateway.CustomPostFilter : Request '//greeting' [1] is waiting on CustomPostFilter
2021-10-03 13:22:14.442 INFO 30184 --- [io-9002-exec-10] c.e.samplegateway.CustomPostFilter : Request '//greeting' [1] is released on CustomPostFilter
2021-10-03 13:22:14.443 INFO 30184 --- [io-9002-exec-10] c.e.samplegateway.CustomPostFilter : Request '//greeting' [1] leaves CustomPostFilter
2021-10-03 13:22:14.452 INFO 30184 --- [io-9002-exec-10] c.e.samplegateway.CustomPostFilter : Request '/goodbye' [3] entered CustomPostFilter
2021-10-03 13:22:14.452 INFO 30184 --- [io-9002-exec-10] c.e.samplegateway.CustomPostFilter : Request '/goodbye' [3] leaves CustomPostFilter
Case 3: 1. GET localhost:9002/greeting WAIT (forwards to a local controller. Delay is emulated by Thread.sleep(20000) in CustomPostFilter) wait a few seconds 2. GET localhost:9002/seeya (routes to another service. Is not filtered by CustomPostFilter)
Result: 2nd request waits till the 1st one finishes
Case 4: 1. GET localhost:9002/goodbye WAIT (propagates request to SampleService. Delay is emulated by Thread.sleep(20000) in CustomPostFilter) wait a few seconds 2. GET localhost:9002/greeting FAST
Result: 2nd request finishes successfully before the 1st one
Logs:
2021-10-03 18:11:24.907 INFO 23556 --- [nio-9002-exec-9] c.e.samplegateway.CustomPostFilter : Request '/goodbye' [4] entered CustomPostFilter
2021-10-03 18:11:24.907 INFO 23556 --- [nio-9002-exec-9] c.e.samplegateway.CustomPostFilter : Request '/goodbye' [4] is waiting on CustomPostFilter
2021-10-03 18:11:29.150 INFO 23556 --- [nio-9002-exec-1] c.e.samplegateway.CustomPostFilter : Request '//greeting' [2] entered CustomPostFilter
2021-10-03 18:11:29.150 INFO 23556 --- [nio-9002-exec-1] c.e.samplegateway.CustomPostFilter : Request '//greeting' [2] leaves CustomPostFilter
2021-10-03 18:11:44.914 INFO 23556 --- [nio-9002-exec-9] c.e.samplegateway.CustomPostFilter : Request '/goodbye' [4] is released on CustomPostFilter
2021-10-03 18:11:44.914 INFO 23556 --- [nio-9002-exec-9] c.e.samplegateway.CustomPostFilter : Request '/goodbye' [4] leaves CustomPostFilter
Case 5: 1. GET localhost:9002/goodbye WAIT (propagates request to SampleService. Delay is emulated by Thread.sleep(20000) in CustomPostFilter) wait a few seconds 2. GET localhost:9002/goodbye FAST
Result: 2nd request finishes successfully before the 1st one
Logs:
2021-10-03 18:21:53.892 INFO 23556 --- [nio-9002-exec-6] c.e.samplegateway.CustomPostFilter : Request '/goodbye' [4] entered CustomPostFilter
2021-10-03 18:21:53.893 INFO 23556 --- [nio-9002-exec-6] c.e.samplegateway.CustomPostFilter : Request '/goodbye' [4] is waiting on CustomPostFilter
2021-10-03 18:21:58.102 INFO 23556 --- [nio-9002-exec-8] c.e.samplegateway.CustomPostFilter : Request '/goodbye' [3] entered CustomPostFilter
2021-10-03 18:21:58.102 INFO 23556 --- [nio-9002-exec-8] c.e.samplegateway.CustomPostFilter : Request '/goodbye' [3] leaves CustomPostFilter
2021-10-03 18:22:13.904 INFO 23556 --- [nio-9002-exec-6] c.e.samplegateway.CustomPostFilter : Request '/goodbye' [4] is released on CustomPostFilter
2021-10-03 18:22:13.904 INFO 23556 --- [nio-9002-exec-6] c.e.samplegateway.CustomPostFilter : Request '/goodbye' [4] leaves CustomPostFilter
Case 6: 1. GET localhost:9002/goodbye WAIT (propagates request to SampleService. Delay is emulated by Thread.sleep(20000) in CustomPostFilter) wait a few seconds 2. GET localhost:9002/seeya (routes to another service. Is not filtered by CustomPostFilter)
Result: 2nd request finishes successfully before the 1st one
As you can see, in the cases 1, 2 and 3 the 2nd request is waiting for the 1st one to finish. I tried to remove the post filter and emulate the delay on the controller level, but in this case everything went well and requests didn't wait.
If anyone has any thoughts on why such behaviour is happening I'd be glad to hear.
Comment From: yalexeyenko
Tested the same cases on Spring Cloud Gateway (https://github.com/yalexeyenko/SpringCloudSampleGateway). The behaviour is the same.
Comment From: OlgaMaciaszek
Hello, @yalexeyenko Spring Cloud Netflix Zuul is no longer supported. If there's an issue with Spring Cloud Gateway, please create a separate GH issue in that repo instead.