Sorry for crossposting. I asked this question on StackOverflow but for some reason, no one seems to have seen it except for me. This issue is getting very pressing now so I'm hoping that someone here will be able to see where I'm going wrong.
This is the SO post: https://stackoverflow.com/questions/60187111/java-webclient-losing-intermittent-responses-when-load-increases
I'm developing a credit card charging server for a hotel booking system that can either be used manually through a web UI or automatically for non-refundable bookings. Each transaction goes through a proxy service (third party cc store, PCI Booking) and from there to the actual payment provider. I then save the responses (Success, card declined, etc), the provider name and the time it took to charge. When I charge manually, everything works fine but when there are several automatic requests firing at the same time, I'm not getting all the responses. Sometimes I get nothing and sometimes the elapsed() handler fires and then nothing.
Here is the code in question:
public Mono<PaymentResponse> doRequest( PaymentTransaction pt ) {
Long bookId = pt.getCardToken().getBookId();
ThreadMXBean bean = ManagementFactory.getThreadMXBean();
logToBoth( "Book ID: " + bookId + ", Total number of threads: " + bean.getThreadCount() );
logToBoth( "Book ID: " + bookId + ", Total number of daemon threads: "
+ bean.getDaemonThreadCount() );
logToBoth( "Book ID: " + bookId + ", Peak thread count: " + bean.getPeakThreadCount() );
if( pt == null ) {
logService.logError( this, "Book ID: " + pt.getCardToken().getBookId()
+ ", doRequest: pt is null!" );
}
else {
logService.logInfo( this, "Book ID: " + pt.getCardToken().getBookId()
+ ", PaymentTransaction health: " + pt.getHealth() );
}
return client.post()
.uri( builder -> builder.path( "/api/paymentGateway" ).build() )
.contentType( MediaType.APPLICATION_JSON )
.body( Mono.just( pt ), PaymentTransaction.class )
.header( "authorization", "APIKEY " + getApiKey() )
.exchange()
.defaultIfEmpty( ClientResponse.create( HttpStatus.I_AM_A_TEAPOT ).build() )
.timeout( Duration.ofMillis( 90000 ) )
.onErrorResume( e -> {
String errorMsg = "Error in payment processing ("
+ pt.getPaymentGateway().getName() + ", BookID: "
+ pt.getCardToken().getBookId() + ", "
+ pt.getCardToken().getCardNumber() + ", "
+ pt.getAmount() + "): " + parseError( e );
logToBoth( errorMsg );
return Mono.error( new Exception( errorMsg ) );
} )
.elapsed()
.flatMap( tuple -> logTime( pt, tuple ) )
.flatMap( response -> {
logToBoth( "Book ID " + pt.getCardToken().getBookId()
+ ". doRequest status: " + response.statusCode().toString() );
if (response.statusCode().is4xxClientError()
|| response.statusCode().is5xxServerError() ) {
logService.logError( this, "Book ID: " + pt.getCardToken().getBookId()
+ ", Error response from provider: "
+ response.statusCode().toString() );
return response.bodyToMono( String.class )
.map( s -> {
String errorMsg = "Book ID " + pt.getCardToken().getBookId()
+ ": " + "Error from PCI Booking: " + s;
logToBoth( errorMsg );
PaymentResponse pr = new PaymentResponse();
String error = encodingService.urlEncode( s );
pr.setPciBookingError( error );
pr.setOperationResultCode( "Failure" );
pr.setOperationResultDescription( "Error" );
pr.setGatewayResultCode( response.statusCode().toString() );
pr.setGatewayResultDescription( error );
pr.setGatewayName( pt.getPaymentGateway().getName() );
pr.setAmount( pt.getAmount() );
pr.setCurrency( pt.getCurrency() );
pr.setGatewayReference( pt.getGatewayReference() );
pr.setCreated( new Date() );
pr.setOperationType( pt.getOperationType() );
return pr;
});
}
else {
logService.logInfo( this, "Book ID: "
+ pt.getCardToken().getBookId() +
", returning payment response" );
return response.bodyToMono( PaymentResponse.class );
}
})
.doOnSuccess( pr -> logToBoth( "Book ID: "
+ pt.getCardToken().getBookId() + ", doRequest successful" ) )
.doOnError( e -> logToBoth( "Book ID: "
+ pt.getCardToken().getBookId()
+ ", doRequest error: " + e.getMessage() ) );
}
private Mono<ClientResponse> logTime( PaymentTransaction pt, Tuple2<Long, ClientResponse> t ) {
ClientResponse cr = t.getT2();
logToBoth( "=> " + pt.getOperationType() + ", Booking: "
+ pt.getCardToken().getBookId() + ", "
+ "Provider: " + pt.getPaymentGateway().getName() + ", "
+ "Amount: " + pt.getAmount() + " " + pt.getCurrency() + ", "
+ "Card: " + pt.getCardToken().getCardNumber() + ", "
+ "Duration: " + t.getT1() + "ms" + ", Status: " + cr.statusCode().toString() );
return Mono.just( cr );
}
This is running in a spring service bean and this is how the WebClient is constructed:
WebClient client = WebClient.builder()
.baseUrl( "https://service.pcibooking.net" )
.build();
i have experienced the issue with as few as 9 requests coming in at the same time. They all reach the payment provider but I appear to get the response for every second request. In those cases, neither of the flatMaps are called but sometimes the elapsed() handler gets called.
I'm logging both to console nad to a database. When this issue happens, the last log I'll see is either the one with "PaymentTransaction health" or the one from logTime().
I added the defaultIfEmpty() just to make sure that I was not getting an empty body. According to PCI Booking, the responses from the payment providers are normal but it seems like I am not receiving them all.
I'm using spring boot and this is my pom:
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://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>2.2.4.RELEASE</version>
<relativePath/> <!-- lookup parent from repository -->
</parent>
<groupId>is.godo</groupId>
<artifactId>pci-server</artifactId>
<version>1.1.0.RELEASE</version>
<packaging>war</packaging>
<name>pci-server</name>
<description>PCI server</description>
<properties>
<java.version>1.8</java.version>
<maven.build.timestamp.format>yyyy.MM.dd</maven.build.timestamp.format>
<docker.tag>${project.version}-${maven.build.timestamp}</docker.tag>
<project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
<project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
<docker.image.prefix> docker.godo.is </docker.image.prefix>
<docker.tag.prefix></docker.tag.prefix>
</properties>
<distributionManagement>
<snapshotRepository>
<id>godo-snapshot</id>
<url>https://repo.godo.is/repository/maven-snapshots/</url>
</snapshotRepository>
<repository>
<id>godo-release</id>
<url>https://repo.godo.is/repository/maven-releases/</url>
</repository>
</distributionManagement>
<dependencies>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-data-jpa</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-test</artifactId>
<scope>test</scope>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-webflux</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-websocket</artifactId>
</dependency>
<dependency>
<groupId>com.fasterxml.jackson.dataformat</groupId>
<artifactId>jackson-dataformat-xml</artifactId>
<version>2.9.7</version>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-tomcat</artifactId>
</dependency>
<dependency>
<groupId>javax.servlet</groupId>
<artifactId>jstl</artifactId>
</dependency>
<dependency>
<groupId>org.apache.tomcat.embed</groupId>
<artifactId>tomcat-embed-jasper</artifactId>
</dependency>
<dependency>
<groupId>org.eclipse.jdt.core.compiler</groupId>
<artifactId>ecj</artifactId>
<version>4.6.1</version>
<scope>provided</scope>
</dependency>
<dependency>
<groupId>org.webjars</groupId>
<artifactId>webjars-locator-core</artifactId>
</dependency>
<dependency>
<groupId>org.webjars</groupId>
<artifactId>webjars-locator</artifactId>
<version>0.36</version>
</dependency>
<dependency>
<groupId>org.webjars</groupId>
<artifactId>sockjs-client</artifactId>
<version>1.0.2</version>
</dependency>
<dependency>
<groupId>org.webjars</groupId>
<artifactId>stomp-websocket</artifactId>
<version>2.3.3</version>
</dependency>
<dependency>
<groupId>org.webjars</groupId>
<artifactId>bootstrap</artifactId>
<version>3.3.7</version>
</dependency>
<dependency>
<groupId>org.webjars</groupId>
<artifactId>jquery</artifactId>
<version>3.1.0</version>
</dependency>
<dependency>
<groupId>mysql</groupId>
<artifactId>mysql-connector-java</artifactId>
<version>8.0.11</version>
<scope>runtime</scope>
</dependency>
<dependency>
<groupId>is.godo</groupId>
<artifactId>godo-api-extended</artifactId>
<version>1.4.8</version>
</dependency>
<dependency>
<groupId>is.godo.core</groupId>
<artifactId>godo-core</artifactId>
<version>2.2.9</version>
</dependency>
<!-- https://mvnrepository.com/artifact/org.apache.commons/commons-lang3 -->
<dependency>
<groupId>org.apache.commons</groupId>
<artifactId>commons-lang3</artifactId>
<version>3.9</version>
</dependency>
<dependency>
<groupId>is.godo.server.property.dto</groupId>
<artifactId>godo-property-server-dto</artifactId>
<version>1.1.9</version>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-security</artifactId>
</dependency>
<dependency>
<groupId>io.jsonwebtoken</groupId>
<artifactId>jjwt</artifactId>
<version>0.9.1</version>
</dependency>
</dependencies>
<build>
<plugins>
<plugin>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-maven-plugin</artifactId>
<configuration>
<addResources>true</addResources>
</configuration>
</plugin>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-jar-plugin</artifactId>
<version>3.0.2</version>
<configuration>
<archive>
<manifest>
<addDefaultImplementationEntries>true</addDefaultImplementationEntries>
<addDefaultSpecificationEntries>true</addDefaultSpecificationEntries>
</manifest>
<manifestFile>${project.build.outputDirectory}/META-INF/MANIFEST.MF</manifestFile>
</archive>
</configuration>
</plugin>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-surefire-plugin</artifactId>
<version>2.20.1</version>
<configuration>
<skipTests>false</skipTests>
</configuration>
</plugin>
<plugin>
<groupId>com.spotify</groupId>
<artifactId>dockerfile-maven-plugin</artifactId>
<version>1.3.6</version>
<dependencies>
<dependency>
<groupId>javax.activation</groupId>
<artifactId>activation</artifactId>
<version>1.1.1</version>
</dependency>
</dependencies>
<configuration>
<repository>${docker.image.prefix}/${project.artifactId}</repository>
<buildArgs>
<WAR_FILE>target/${project.build.finalName}.war</WAR_FILE>
</buildArgs>
<tag>${docker.tag.prefix
</configuration>
</plugin>
</plugins>
</build>
</project>
It might be relevant that the doRequest function returns a Mono which is then flatMapped and another service called that stores information about the payment in the hotel booking system. This function can take several seconds to complete.
I thought this might be a threading issue so I tried changing some parameters but they don't seem to have an effect. At the moment, I have these tomcat parameters set:
server.tomcat.max-threads: 200
server.tomcat.min-spare-threads: 50
Any help would be greatly appreciated. I'm totally at a loss here.
Thanks, Gísli
Comment From: rstoyanchev
Sorry for the slow response.
when there are several automatic requests firing at the same time, I'm not getting all the responses.
How are these requests fired exactly? If they are performed within another operator like flatMap or zip it could be that an error (or timeout) from one causes others to be cancelled. You'd have to use delay the errors then, e.g. with flatMapDelayError.
Sometimes I get nothing and sometimes the elapsed() handler fires and then nothing.
How do you know the elapsed handler fires exactly? Is it through the logTime method and if so are you saying that there are no more log statements after that, e.g. from the flatMap right after it?
You can try and insert .log("some.category") in different places (e.g. after exchange, between flatMap, etc) to see what happens. Also try with and without elapsed.
Comment From: spring-projects-issues
If you would like us to look at this issue, please provide the requested information. If the information is not provided within the next 7 days this issue will be closed.
Comment From: gislileifs
Thanks a lot for the response. I believe I know the cause of my problems. I was actually calling my springboot app with javascript on the client side using http POST and on the server side, I was returning the Mono to the client. Despite me setting all sorts of timeouts both on the client side and server side, it still seemed like the browser was never waiting longer than 30 seconds. And this operation can take a full minute. So I guess if the client stops listening, the server side doesn't continue since no one is interested in the response anymore.
What I ended up doing was switching to websockets instead of http and that solved all my problems. Then I was subscribing to the response on the server side and wasn't restricted by browser timeouts.
Thanks a lot! Gísli
Comment From: bclozel
Thanks for letting us know!