SAP / cloud-sdk-java

Use the SAP Cloud SDK for Java to reduce development effort when building applications on SAP Business Technology Platform that communicate with SAP solutions and services such as SAP S/4HANA Cloud, SAP SuccessFactors, and many others.
Apache License 2.0
22 stars 13 forks source link

Frequent CSRF Token Fetching Error #357

Closed VerletzterDigitusPedis closed 7 months ago

VerletzterDigitusPedis commented 7 months ago

Hello everyone,

Issue Description

We are using the SAP Cloud SDK to connect with S/4HANA (on premise) in order to transfer business data from our custom coded source systems to S/4HANA. We are currently using version 5.2.0 of the Java SDK. For our VDM we are using the generator, so the dependency is

 <dependency>
            <groupId>com.sap.cloud.sdk.datamodel</groupId>
            <artifactId>odata-core</artifactId>
            <version>5.2.0</version>
</dependency>

With the configuration

<configuration>
                            <inputDirectory>${project.basedir}/edmx</inputDirectory>
                            <outputDirectory>${project.build.directory}/vdm</outputDirectory>
                            <deleteOutputDirectory>true</deleteOutputDirectory>
                            <packageName>our.company</packageName>
                            <nameSource>NAME</nameSource>
                            <defaultBasePath>/sap/opu/odata/sap/</defaultBasePath>
                            <compileScope>COMPILE</compileScope>
                            <serviceMethodsPerEntitySet>true</serviceMethodsPerEntitySet>
</configuration>

We use the SAP Cloud SDK in a multi-threaded way and sometimes receive errors where the CSRF token fetching fails. I would like to know if this is a problem with the SAP Cloud SDK itself or something that has to be configured in S/4HANA itself. To me it seems like multiple HEAD Requests at the same time seem to be the problem. We also noticed a pattern, where it typically happened every 5 minutes for a few requests. I also tried to reproduce it in an isolated test and I was at least somewhat successful. Here is the code:

package our.company;

import com.sap.cloud.sdk.cloudplatform.connectivity.AuthenticationType;
import com.sap.cloud.sdk.cloudplatform.connectivity.DefaultHttpDestination;
import com.sap.cloud.sdk.cloudplatform.connectivity.Destination;
import com.sap.cloud.sdk.cloudplatform.security.BasicCredentials;
import com.sap.cloud.sdk.datamodel.odata.client.exception.ODataConnectionException;
import com.sap.cloud.sdk.datamodel.odata.client.exception.ODataResponseException;
import com.sap.cloud.sdk.datamodel.odata.helper.ModificationResponse;
import our.company.namespaces.salesorder.SalesOrder;
import our.company.namespaces.salesorder.SalesOrderFluentHelper;
import our.company.services.DefaultSalesOrderService;
import our.company.services.SalesOrderService;
import org.junit.jupiter.api.Test;
import org.springframework.scheduling.concurrent.CustomizableThreadFactory;

import java.time.LocalDateTime;
import java.util.List;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.Executor;
import java.util.concurrent.Executors;
import java.util.concurrent.FutureTask;
import java.util.stream.Collectors;
import java.util.stream.IntStream;

class TokenFetchingTest {

    public static final Destination destination = DefaultHttpDestination.builder("http://our.company.lan:8000/sap/opu/odata/sap/")
            .name("custom-destination")
            .authenticationType(AuthenticationType.BASIC_AUTHENTICATION)
            .basicCredentials(new BasicCredentials("OUR_USER", "OUR_PASSWORD"))
            .header("sap-client", "300")
            .build();
    public static final Executor threadPool = Executors.newFixedThreadPool(
            15, new CustomizableThreadFactory("worker-"));
    SalesOrderService orderClient;

    @Test
    void happy_path_for_order_creation_test() throws InterruptedException {
        SalesOrderService orderClient = new DefaultSalesOrderService();
        Runnable createAndDeleteOrder = () -> {
            try {
                ModificationResponse<SalesOrder> salesOrderModificationResponse = orderClient.createSalesOrder(SalesOrder.builder()
                                //Stuff to build a valid order
                                .build())
                        .executeRequest(destination);

                SalesOrder createdSalesOrder = salesOrderModificationResponse.getModifiedEntity();
                orderClient.deleteSalesOrder(createdSalesOrder).executeRequest(destination);
            } catch (ODataResponseException e) {
                if (e.getHttpBody().contains("CSRF token validation failed")) {
                    System.out.println("Token Fetching Error. Time is: " + LocalDateTime.now());
                } else {
                    System.out.println("Other Error:" + e.getCause());
                }
            } catch (ODataConnectionException e) {
                System.out.println("Other Error:" + e.getCause());
            }
        };
        // Create a List of 100000 orders to create and wait for completion
        List<FutureTask<Object>> tasks = IntStream.rangeClosed(1, 100000).mapToObj(i -> new FutureTask<>(createAndDeleteOrder, null)).collect(Collectors.toList());
        tasks.forEach(task -> threadPool.execute(task));
        try {
            for (FutureTask t : tasks) {
                t.get();
            }
            System.out.println("Finished Runnables");
        } catch (InterruptedException | ExecutionException e) {
            System.out.println("Interrupted");
        }
    }
}

Token Fetching Error. Time is: 2024-03-11T12:33:04.305538800
Token Fetching Error. Time is: 2024-03-11T12:33:04.305538800
Token Fetching Error. Time is: 2024-03-11T12:33:04.305538800
Token Fetching Error. Time is: 2024-03-11T12:33:04.306539600
Token Fetching Error. Time is: 2024-03-11T12:33:04.315769200
Token Fetching Error. Time is: 2024-03-11T12:33:04.333116700
Token Fetching Error. Time is: 2024-03-11T12:33:04.335068100
Token Fetching Error. Time is: 2024-03-11T12:33:04.353210900
Token Fetching Error. Time is: 2024-03-11T12:33:04.654094300
Token Fetching Error. Time is: 2024-03-11T12:33:05.522386400
Token Fetching Error. Time is: 2024-03-11T12:38:04.474535
Token Fetching Error. Time is: 2024-03-11T12:43:04.666723
Token Fetching Error. Time is: 2024-03-11T12:48:04.605312
Token Fetching Error. Time is: 2024-03-11T12:53:04.630486700
Token Fetching Error. Time is: 2024-03-11T12:58:04.683986
Token Fetching Error. Time is: 2024-03-11T13:18:04.876563200
Token Fetching Error. Time is: 2024-03-11T13:33:04.972514
Token Fetching Error. Time is: 2024-03-11T13:38:04.975472500
Token Fetching Error. Time is: 2024-03-11T13:43:05.143490200
Token Fetching Error. Time is: 2024-03-11T13:43:05.143490200
Token Fetching Error. Time is: 2024-03-11T13:43:05.143490200
Token Fetching Error. Time is: 2024-03-11T13:43:05.162488200
Token Fetching Error. Time is: 2024-03-11T13:48:05.263970
Token Fetching Error. Time is: 2024-03-11T14:13:05.456609900
Token Fetching Error. Time is: 2024-03-11T14:13:05.459609300
Token Fetching Error. Time is: 2024-03-11T14:18:05.506159700
Token Fetching Error. Time is: 2024-03-11T14:18:05.506159700
Token Fetching Error. Time is: 2024-03-11T14:38:05.604963900
Token Fetching Error. Time is: 2024-03-11T14:53:05.741766300

This is a part of the output of the test code. This shows a similair pattern. A lot of requests fail at the same time, then everything seems to be fine for 5 minutes and the error continues.

I should add, that we also do load testing via K6 with virtual users and do not have the same problem there. Same with PI/CPI where we also use ODATA directly (although the PI handles the token fetching itself). Can you explain why and how it happens and maybe even the 5 minute pattern?

Impact / Priority

This affects our development and testing phase. We are discussing whether we should keep the CSRF mechanism at all.

Impact: Impaired

Timeline: Implmentation is scheduled to be finished in September but it already impairs our testing.

Error Message

SAP responded with OData Error: CSRF token validation failed

If application logs are needed, then I can provide them as well. Given the amount of requests needed to reproduce this error, I omitted them for now. If you need a specific part, then just give me a heads up and I will try to add them.

[INFO] +- org.springframework.boot:spring-boot-starter-jdbc:jar:2.6.1:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter:jar:2.6.1:compile
[INFO] |  |  +- org.springframework.boot:spring-boot-starter-logging:jar:2.6.1:compile
[INFO] |  |  |  +- ch.qos.logback:logback-classic:jar:1.2.7:compile
[INFO] |  |  |  |  \- ch.qos.logback:logback-core:jar:1.2.7:compile
[INFO] |  |  |  +- org.apache.logging.log4j:log4j-to-slf4j:jar:2.14.1:compile
[INFO] |  |  |  |  \- org.apache.logging.log4j:log4j-api:jar:2.14.1:compile
[INFO] |  |  |  \- org.slf4j:jul-to-slf4j:jar:1.7.32:compile
[INFO] |  |  +- jakarta.annotation:jakarta.annotation-api:jar:1.3.5:compile
[INFO] |  |  \- org.yaml:snakeyaml:jar:1.29:compile
[INFO] |  +- com.zaxxer:HikariCP:jar:4.0.3:compile
[INFO] |  \- org.springframework:spring-jdbc:jar:5.3.13:compile
[INFO] |     +- org.springframework:spring-beans:jar:5.3.13:compile
[INFO] |     \- org.springframework:spring-tx:jar:5.3.13:compile
[INFO] +- org.springframework.boot:spring-boot-configuration-processor:jar:2.6.1:compile
[INFO] +- org.springframework.boot:spring-boot-devtools:jar:2.6.1:runtime (optional) 
[INFO] |  +- org.springframework.boot:spring-boot:jar:2.6.1:compile
[INFO] |  |  \- org.springframework:spring-context:jar:5.3.13:compile
[INFO] |  \- org.springframework.boot:spring-boot-autoconfigure:jar:2.6.1:compile
[INFO] +- org.springframework.boot:spring-boot-starter-webflux:jar:2.6.1:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter-json:jar:2.6.1:compile
[INFO] |  |  +- com.fasterxml.jackson.datatype:jackson-datatype-jdk8:jar:2.13.0:compile
[INFO] |  |  +- com.fasterxml.jackson.datatype:jackson-datatype-jsr310:jar:2.13.0:compile
[INFO] |  |  \- com.fasterxml.jackson.module:jackson-module-parameter-names:jar:2.13.0:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter-reactor-netty:jar:2.6.1:compile
[INFO] |  |  \- io.projectreactor.netty:reactor-netty-http:jar:1.0.13:compile
[INFO] |  |     +- io.netty:netty-codec-http:jar:4.1.70.Final:compile
[INFO] |  |     |  +- io.netty:netty-common:jar:4.1.70.Final:compile
[INFO] |  |     |  +- io.netty:netty-buffer:jar:4.1.70.Final:compile
[INFO] |  |     |  +- io.netty:netty-transport:jar:4.1.70.Final:compile
[INFO] |  |     |  +- io.netty:netty-codec:jar:4.1.70.Final:compile
[INFO] |  |     |  \- io.netty:netty-handler:jar:4.1.70.Final:compile
[INFO] |  |     +- io.netty:netty-codec-http2:jar:4.1.70.Final:compile
[INFO] |  |     +- io.netty:netty-resolver-dns:jar:4.1.70.Final:compile
[INFO] |  |     |  +- io.netty:netty-resolver:jar:4.1.70.Final:compile
[INFO] |  |     |  \- io.netty:netty-codec-dns:jar:4.1.70.Final:compile
[INFO] |  |     +- io.netty:netty-resolver-dns-native-macos:jar:osx-x86_64:4.1.70.Final:compile
[INFO] |  |     |  \- io.netty:netty-resolver-dns-classes-macos:jar:4.1.70.Final:compile
[INFO] |  |     +- io.netty:netty-transport-native-epoll:jar:linux-x86_64:4.1.70.Final:compile
[INFO] |  |     |  +- io.netty:netty-transport-native-unix-common:jar:4.1.70.Final:compile
[INFO] |  |     |  \- io.netty:netty-transport-classes-epoll:jar:4.1.70.Final:compile
[INFO] |  |     \- io.projectreactor.netty:reactor-netty-core:jar:1.0.13:compile
[INFO] |  |        \- io.netty:netty-handler-proxy:jar:4.1.70.Final:compile
[INFO] |  |           \- io.netty:netty-codec-socks:jar:4.1.70.Final:compile
[INFO] |  +- org.springframework:spring-web:jar:5.3.13:compile
[INFO] |  \- org.springframework:spring-webflux:jar:5.3.13:compile
[INFO] |     \- io.projectreactor:reactor-core:jar:3.4.12:compile
[INFO] |        \- org.reactivestreams:reactive-streams:jar:1.0.3:compile
[INFO] +- org.springframework.boot:spring-boot-starter-aop:jar:2.6.1:compile
[INFO] |  +- org.springframework:spring-aop:jar:5.3.13:compile
[INFO] |  \- org.aspectj:aspectjweaver:jar:1.9.7:compile
[INFO] +- org.springframework.boot:spring-boot-starter-actuator:jar:2.6.1:compile
[INFO] |  +- org.springframework.boot:spring-boot-actuator-autoconfigure:jar:2.6.1:compile
[INFO] |  |  \- org.springframework.boot:spring-boot-actuator:jar:2.6.1:compile
[INFO] |  \- io.micrometer:micrometer-core:jar:1.8.0:compile
[INFO] |     +- org.hdrhistogram:HdrHistogram:jar:2.1.12:compile
[INFO] |     \- org.latencyutils:LatencyUtils:jar:2.0.3:runtime
[INFO] +- org.springframework.boot:spring-boot-starter-web:jar:2.6.1:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter-tomcat:jar:2.6.1:compile
[INFO] |  |  +- org.apache.tomcat.embed:tomcat-embed-core:jar:9.0.55:compile
[INFO] |  |  +- org.apache.tomcat.embed:tomcat-embed-el:jar:9.0.55:compile
[INFO] |  |  \- org.apache.tomcat.embed:tomcat-embed-websocket:jar:9.0.55:compile
[INFO] |  \- org.springframework:spring-webmvc:jar:5.3.13:compile
[INFO] |     \- org.springframework:spring-expression:jar:5.3.13:compile
[INFO] +- org.springframework.boot:spring-boot-starter-cache:jar:2.6.1:compile
[INFO] |  \- org.springframework:spring-context-support:jar:5.3.13:compile
[INFO] +- com.h2database:h2:jar:1.4.200:runtime
[INFO] +- com.oracle.database.jdbc:ojdbc8:jar:21.3.0.0:runtime
[INFO] +- org.springframework.boot:spring-boot-starter-test:jar:2.6.1:test
[INFO] |  +- org.springframework.boot:spring-boot-test:jar:2.6.1:test
[INFO] |  +- org.springframework.boot:spring-boot-test-autoconfigure:jar:2.6.1:test
[INFO] |  +- com.jayway.jsonpath:json-path:jar:2.6.0:test
[INFO] |  |  \- net.minidev:json-smart:jar:2.4.7:test
[INFO] |  |     \- net.minidev:accessors-smart:jar:2.4.7:test
[INFO] |  +- jakarta.xml.bind:jakarta.xml.bind-api:jar:2.3.3:test
[INFO] |  |  \- jakarta.activation:jakarta.activation-api:jar:1.2.2:test
[INFO] |  +- org.assertj:assertj-core:jar:3.21.0:test
[INFO] |  +- org.hamcrest:hamcrest:jar:2.2:test
[INFO] |  +- org.junit.jupiter:junit-jupiter:jar:5.8.1:test
[INFO] |  |  +- org.junit.jupiter:junit-jupiter-api:jar:5.8.1:test
[INFO] |  |  |  +- org.opentest4j:opentest4j:jar:1.2.0:test
[INFO] |  |  |  +- org.junit.platform:junit-platform-commons:jar:1.8.1:test
[INFO] |  |  |  \- org.apiguardian:apiguardian-api:jar:1.1.2:test
[INFO] |  |  +- org.junit.jupiter:junit-jupiter-params:jar:5.8.1:test
[INFO] |  |  \- org.junit.jupiter:junit-jupiter-engine:jar:5.8.1:test
[INFO] |  |     \- org.junit.platform:junit-platform-engine:jar:1.8.1:test
[INFO] |  +- org.mockito:mockito-core:jar:4.0.0:test
[INFO] |  |  +- net.bytebuddy:byte-buddy:jar:1.11.22:test
[INFO] |  |  +- net.bytebuddy:byte-buddy-agent:jar:1.11.22:test
[INFO] |  |  \- org.objenesis:objenesis:jar:3.2:test
[INFO] |  +- org.mockito:mockito-junit-jupiter:jar:4.0.0:test
[INFO] |  +- org.skyscreamer:jsonassert:jar:1.5.0:test
[INFO] |  +- org.springframework:spring-core:jar:5.3.13:compile
[INFO] |  |  \- org.springframework:spring-jcl:jar:5.3.13:compile
[INFO] |  \- org.xmlunit:xmlunit-core:jar:2.8.3:test
[INFO] +- com.tngtech.archunit:archunit-junit5:jar:0.17.0:test
[INFO] |  +- com.tngtech.archunit:archunit-junit5-api:jar:0.17.0:test
[INFO] |  |  \- com.tngtech.archunit:archunit:jar:0.17.0:test
[INFO] |  \- com.tngtech.archunit:archunit-junit5-engine:jar:0.17.0:test
[INFO] |     \- com.tngtech.archunit:archunit-junit5-engine-api:jar:0.17.0:test
[INFO] +- io.github.resilience4j:resilience4j-spring-boot2:jar:1.7.0:compile
[INFO] |  +- io.vavr:vavr:jar:0.10.2:compile
[INFO] |  |  \- io.vavr:vavr-match:jar:0.10.2:compile
[INFO] |  +- org.slf4j:slf4j-api:jar:1.7.32:compile
[INFO] |  +- io.github.resilience4j:resilience4j-spring:jar:1.7.0:compile
[INFO] |  |  +- io.github.resilience4j:resilience4j-annotations:jar:1.7.0:compile
[INFO] |  |  +- io.github.resilience4j:resilience4j-consumer:jar:1.7.0:compile
[INFO] |  |  |  +- io.github.resilience4j:resilience4j-core:jar:1.7.0:compile
[INFO] |  |  |  \- io.github.resilience4j:resilience4j-circularbuffer:jar:1.7.0:compile
[INFO] |  |  \- io.github.resilience4j:resilience4j-framework-common:jar:1.7.0:compile
[INFO] |  |     +- io.github.resilience4j:resilience4j-circuitbreaker:jar:1.7.0:compile
[INFO] |  |     +- io.github.resilience4j:resilience4j-ratelimiter:jar:1.7.0:compile
[INFO] |  |     +- io.github.resilience4j:resilience4j-retry:jar:1.7.0:compile
[INFO] |  |     +- io.github.resilience4j:resilience4j-bulkhead:jar:1.7.0:compile
[INFO] |  |     \- io.github.resilience4j:resilience4j-timelimiter:jar:1.7.0:compile
[INFO] |  \- io.github.resilience4j:resilience4j-micrometer:jar:1.7.0:compile
[INFO] +- org.mockito:mockito-inline:jar:4.0.0:test
[INFO] +- com.squareup.okhttp3:mockwebserver:jar:4.9.3:test
[INFO] |  +- com.squareup.okhttp3:okhttp:jar:4.9.3:test
[INFO] |  |  +- com.squareup.okio:okio:jar:2.8.0:test
[INFO] |  |  |  \- org.jetbrains.kotlin:kotlin-stdlib-common:jar:1.6.0:test
[INFO] |  |  \- org.jetbrains.kotlin:kotlin-stdlib:jar:1.6.0:test
[INFO] |  |     \- org.jetbrains:annotations:jar:13.0:test
[INFO] |  +- junit:junit:jar:4.13.2:test
[INFO] |  |  \- org.hamcrest:hamcrest-core:jar:2.2:test
[INFO] |  \- org.jetbrains.kotlin:kotlin-stdlib-jdk8:jar:1.6.0:test
[INFO] |     \- org.jetbrains.kotlin:kotlin-stdlib-jdk7:jar:1.6.0:test
[INFO] +- com.github.tomakehurst:wiremock:jar:2.27.2:test
[INFO] |  +- org.eclipse.jetty:jetty-server:jar:9.4.44.v20210927:test
[INFO] |  |  +- javax.servlet:javax.servlet-api:jar:4.0.1:test
[INFO] |  |  +- org.eclipse.jetty:jetty-http:jar:9.4.44.v20210927:test
[INFO] |  |  \- org.eclipse.jetty:jetty-io:jar:9.4.44.v20210927:test
[INFO] |  +- org.eclipse.jetty:jetty-servlet:jar:9.4.44.v20210927:test
[INFO] |  |  +- org.eclipse.jetty:jetty-security:jar:9.4.44.v20210927:test
[INFO] |  |  \- org.eclipse.jetty:jetty-util-ajax:jar:9.4.44.v20210927:test
[INFO] |  +- org.eclipse.jetty:jetty-servlets:jar:9.4.44.v20210927:test
[INFO] |  |  +- org.eclipse.jetty:jetty-continuation:jar:9.4.44.v20210927:test
[INFO] |  |  \- org.eclipse.jetty:jetty-util:jar:9.4.44.v20210927:test
[INFO] |  +- org.eclipse.jetty:jetty-webapp:jar:9.4.44.v20210927:test
[INFO] |  |  \- org.eclipse.jetty:jetty-xml:jar:9.4.44.v20210927:test
[INFO] |  +- org.eclipse.jetty:jetty-proxy:jar:9.4.44.v20210927:test
[INFO] |  |  \- org.eclipse.jetty:jetty-client:jar:9.4.44.v20210927:test
[INFO] |  +- com.fasterxml.jackson.core:jackson-core:jar:2.13.0:compile
[INFO] |  +- com.fasterxml.jackson.core:jackson-annotations:jar:2.13.0:compile
[INFO] |  +- com.fasterxml.jackson.core:jackson-databind:jar:2.13.0:compile
[INFO] |  +- org.apache.httpcomponents:httpclient:jar:4.5.13:compile
[INFO] |  |  \- commons-codec:commons-codec:jar:1.15:compile
[INFO] |  +- org.xmlunit:xmlunit-legacy:jar:2.8.3:test
[INFO] |  +- org.xmlunit:xmlunit-placeholders:jar:2.8.3:test
[INFO] |  +- org.ow2.asm:asm:jar:7.0:test
[INFO] |  +- net.sf.jopt-simple:jopt-simple:jar:5.0.3:test
[INFO] |  +- org.apache.commons:commons-lang3:jar:3.12.0:compile
[INFO] |  +- com.github.jknack:handlebars:jar:4.0.7:test
[INFO] |  |  \- org.antlr:antlr4-runtime:jar:4.7.1:test
[INFO] |  +- com.github.jknack:handlebars-helpers:jar:4.0.7:test
[INFO] |  +- com.flipkart.zjsonpatch:zjsonpatch:jar:0.4.4:test
[INFO] |  \- commons-fileupload:commons-fileupload:jar:1.4:test
[INFO] |     \- commons-io:commons-io:jar:2.2:test
[INFO] +- com.sap.cloud.sdk:sdk-bom:pom:5.2.0:import
[INFO] +- com.sap.cloud.sdk.s4hana:s4hana-connectivity:jar:5.2.0:compile
[INFO] |  +- com.sap.cloud.sdk.cloudplatform:cloudplatform-core:jar:5.2.0:compile
[INFO] |  +- com.sap.cloud.sdk.cloudplatform:cloudplatform-connectivity:jar:5.2.0:compile
[INFO] |  |  +- com.sap.cloud.sdk.cloudplatform:resilience-api:jar:5.2.0:compile
[INFO] |  |  |  \- com.sap.cloud.sdk.cloudplatform:tenant:jar:5.2.0:compile
[INFO] |  |  +- com.sap.cloud.environment.servicebinding.api:java-core-api:jar:0.10.1:compile
[INFO] |  |  +- com.sap.cloud.environment.servicebinding.api:java-access-api:jar:0.10.1:compile
[INFO] |  |  +- com.mikesamuel:json-sanitizer:jar:1.2.3:compile
[INFO] |  |  +- com.auth0:java-jwt:jar:4.4.0:compile
[INFO] |  |  +- org.bouncycastle:bcprov-jdk18on:jar:1.77:compile
[INFO] |  |  \- org.bouncycastle:bcpkix-jdk18on:jar:1.77:compile
[INFO] |  |     \- org.bouncycastle:bcutil-jdk18on:jar:1.77:compile
[INFO] |  +- com.sap.cloud.sdk.cloudplatform:connectivity-apache-httpclient4:jar:5.2.0:compile
[INFO] |  |  +- com.sap.cloud.sdk.cloudplatform:caching:jar:5.2.0:compile
[INFO] |  |  \- com.github.ben-manes.caffeine:caffeine:jar:2.9.2:compile
[INFO] |  +- com.sap.cloud.sdk.cloudplatform:security:jar:5.2.0:compile
[INFO] |  +- com.sap.cloud.sdk.datamodel:fluent-result:jar:5.2.0:compile
[INFO] |  +- org.slf4j:jcl-over-slf4j:jar:1.7.32:runtime
[INFO] |  +- com.google.code.gson:gson:jar:2.8.9:compile
[INFO] |  \- org.apache.httpcomponents:httpcore:jar:4.4.14:compile
[INFO] +- our.company:-sap-model:jar:2022.02.0:compile
[INFO] |  \- com.sap.cloud.sdk.datamodel:odata-core:jar:5.2.0:compile
[INFO] |     \- com.sap.cloud.sdk.datamodel:odata-client:jar:5.2.0:compile
[INFO] +- com.sap.cloud.sdk.s4hana:s4hana-core:jar:5.2.0:compile
[INFO] +- com.sap.hcp.cf.logging:cf-java-logging-support-logback:jar:3.5.7:test
[INFO] |  \- com.sap.hcp.cf.logging:cf-java-logging-support-core:jar:3.5.7:test
[INFO] |     \- com.fasterxml.jackson.jr:jackson-jr-objects:jar:2.13.0:test
[INFO] +- org.mapstruct:mapstruct:jar:1.5.0.Beta2:provided
[INFO] +- org.projectlombok:lombok:jar:1.18.20:provided
[INFO] +- org.springframework:spring-test:jar:5.3.13:compile
[INFO] +- org.apache.commons:commons-configuration2:jar:2.9.0:compile
[INFO] |  +- org.apache.commons:commons-text:jar:1.10.0:compile
[INFO] |  \- commons-logging:commons-logging:jar:1.2:compile
[INFO] +- commons-beanutils:commons-beanutils:jar:1.9.4:compile
[INFO] |  \- commons-collections:commons-collections:jar:3.2.2:compile
[INFO] +- com.google.guava:guava:jar:32.1.3-jre:compile
[INFO] |  +- com.google.guava:failureaccess:jar:1.0.1:compile
[INFO] |  +- com.google.guava:listenablefuture:jar:9999.0-empty-to-avoid-conflict-with-guava:compile
[INFO] |  +- com.google.code.findbugs:jsr305:jar:3.0.2:compile
[INFO] |  +- org.checkerframework:checker-qual:jar:3.37.0:compile
[INFO] |  +- com.google.errorprone:error_prone_annotations:jar:2.21.1:compile
[INFO] |  \- com.google.j2objc:j2objc-annotations:jar:2.8:compile
[INFO] \- io.micrometer:micrometer-registry-prometheus:jar:1.8.0:runtime
[INFO]    \- io.prometheus:simpleclient_common:jar:0.12.0:runtime
[INFO]       \- io.prometheus:simpleclient:jar:0.12.0:runtime
[INFO]          +- io.prometheus:simpleclient_tracer_otel:jar:0.12.0:runtime
[INFO]          |  \- io.prometheus:simpleclient_tracer_common:jar:0.12.0:runtime
[INFO]          \- io.prometheus:simpleclient_tracer_otel_agent:jar:0.12.0:runtime

Project Details

Checklist

Thank you for your valuable time and your support :)

Johannes-Schneider commented 7 months ago

Hi @VerletzterDigitusPedis,

thanks for reaching out to us.

What you are observing is part of a problem we (the Cloud SDK) decided not to tap into: User session management.

Explanation Let me try to give a very brief summary of what is going on here in the background. Your S/4 system requires a CSRF token for any request that tries to manipulate data. Such a token can be requested by attaching an `x-csrf-token: fetch` header to a "pre-flight" request (i.e. a `HEAD` request against the service root path). Within the response, the S/4 system will return an `x-csrf-token` header with a value that is internally (within the S/4 system) matched to a user session. **Additionally** (and this is the most important part), the S/4 system also sends an HTTP cookie in its response. This cookie ends up being stored within the HTTP client instance that was used to send the request. Now, as you may know, the Cloud SDK implements a [cache for HTTP clients](https://sap.github.io/cloud-sdk/docs/java/features/connectivity/http-client#configuring-the-cache) to reduce the amount of time it takes for subsequent requests to be executed. This cache, by the way, is the reason why you are seeing the "every 5 minutes"-pattern: The default caching duration for our HTTP clients is exactly 5 minutes. Now in a single-threaded scenario, all of this comes down to a flow like this: ``` myService.createMyEntity(myEntity).executeRequest(myDestination) HttpClientAccessor.getHttpClient(myDestination) -> check if client is cached <- no -> create new http client <- new http client (using the returned HTTP client) -> check if csrf token header is present <- no -> fetch csrf token -> HEAD http://s4/myService/ x-csrf-token: fetch <- 200 x-csrf-token: some-token Set-Cookie: some-cookie (using the csrf token) -> POST http://s4/myService/myEntity x-csrf-token: some-token Cookie: some-cookie <- 200 --- (end of first OData request) myService.updateMyEntity(myEntity).executeRequest(myDestination) HttpClientAccessor.getHttpClient(myDestination) -> check if client is cached <- yes <- cached http client (using the returned HTTP client) -> check if csrf token header is present <- no -> fetch csrf token -> HEAD http://s4/myService/ x-csrf-token: fetch cookie: some-cookie <- 200 x-csrf-token: some-other-token Set-Cookie: some-other-cookie (using the csrf token) -> PATCH http://s4/myService/myEntity x-csrf-token: some-other-token Cookie: some-other-cookie <- 200 ``` This flow somewhat works as expected, but is of course suboptimal as we are running additional HEAD requests that are not necessary. In a multi-threaded scenario (like yours), the situation changes. If we are running multiple OData requests in parallel, there is a chance that we are fetching two (or more) CSRF tokens in parallel. This is a problem because the HTTP client instance is actually **shared** between all threads. As such, we end up overwriting the csrf-cookie in our shared HTTP client instance every time we are retrieving the csrf token from the S/4 system. By doing that, we end up with a mismatch between the `x-csrf-token` header and the csrf-cookie within our `POST`/`PATCH` request. This mismatch is causing the error you are seeing. **NOTE** I'm not an expert of how exactly all of this CSRF logic is implemented in the S/4 backend system. So please take my explanation with a grain of salt.

Proposed Solution

To solve the issue, I recommend running the pre-flight (i.e. HEAD) request manually and just once.

Here is an example of how that could look:

final HttpClient httpClient = HttpClientAccessor.getHttpClient(destination);
final CsrfToken csrfToken = new DefaultCsrfTokenRetriever().retrieveCsrfToken(httpClient, SdkGroceryStoreService.DEFAULT_SERVICE_PATH);

// execute X times
ThreadContextExecutors.execute(() -> {
    new DefaultSdkGroceryStoreService()
            .deleteShelf(myShelf)
            .withHeader(DefaultCsrfTokenRetriever.X_CSRF_TOKEN_HEADER_KEY, csrfToken.getToken())
            .toRequest()
            .execute(httpClient);
});

Hope that makes sense!

Best regards, Johannes

VerletzterDigitusPedis commented 7 months ago

Hi Johannes, thank you for the great explanation and your deep insight. I tried to reproduce your suggestions in a test case and it seems to work. From my tests with Postman I assumed that the CSRF Token is only valid for a single request. In combination with the HTTP Client Cache and all of the given information we now have a rough idea on how to tackle this issue. Obviously the CSRF Token does not have an infinite validity. Therefore we will need to implement some kind of session store with a locking mechanism that is accessed by the threads once the token loses the validity. I assume that this is part of your proposed solution or would there be an easier way?

Kind Regards Marlon / VerletzterDigitusPedis

Johannes-Schneider commented 7 months ago

Hi @VerletzterDigitusPedis,

Therefore we will need to implement some kind of session store with a locking mechanism that is accessed by the threads once the token loses the validity. I assume that this is part of your proposed solution or would there be an easier way?

I think that sounds like a good idea. Unfortunately, though, as I stated earlier: We consciously decided to not provide any convenience from our side as we figured that we cannot provide a reasonable solution without making (potentially) too over specific assumptions on what applications actually want/need.

For example, should there be a way for applications to terminate an existing user session early? If so, how would that work? Also: Maybe some user sessions can be extended without re-fetching the CSRF token? Or maybe the session (in backend-side) is automatically extended upon using the CSRF token? If so, for how long?

Therefore, we decided not to implement support for user session management.

Best regards, Johannes