Fix flaky ProductExecutorConfigurationScenario8IntTest

de-jcup commented 11 months ago

Situation

We have a flaky integration test: ProductExecutorConfigurationScenario8IntTest.

Analyze

Sometimes we have following error:

java.lang.NullPointerException: Cannot invoke "java.util.UUID.toString()" because "sechubJobUUID" is null
    at com.mercedesbenz.sechub.test.SecHubTestURLBuilder.buildAdminDownloadsZipFileContainingFullScanDataFor(SecHubTestURLBuilder.java:313)
    at com.mercedesbenz.sechub.integrationtest.api.AsUser.downloadFullScanDataFor(AsUser.java:844)
    at com.mercedesbenz.sechub.integrationtest.scenario8.ProductExecutorConfigurationScenario8IntTest.two_profiles_with_same_config_inside_for_same_product_result_in_scanlog_with_one_metadata_and_result_entry_for_product(ProductExecutorConfigurationScenario8IntTest.java:168)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    at com.mercedesbenz.sechub.integrationtest.api.IntegrationTestSetup$IntegrationTestStatement.evaluate(IntegrationTestSetup.java:229)
    at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:299)
    at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:293)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.lang.Thread.run(Thread.java:833)

The test source part is:

        createOrResetProfile(profileId2);

        as(SUPER_ADMIN).
            addConfigurationToProfile(profileId2,config1UUID).
            addProjectsToProfile(profileId2, PROJECT_1);

        /* execute */
        ExecutionResult result = as(USER_1).createWebScanAndFetchScanData(PROJECT_1);

        /* test */
        File zipfile = as(SUPER_ADMIN).downloadFullScanDataFor(result.getSechubJobUUID());

And the execution result has sometimes no SecHub job uuid which leads to NPE.

The test console log contained:

13:57:31.059 [Time-limited test] INFO com.mercedesbenz.sechub.integrationtest.internal.SecHubClientExecutor - Command output:
 _____           _   _       _     
/  ___|         | | | |     | |    
\ `--.  ___  ___| |_| |_   _| |__  
 `--. \/ _ \/ __|  _  | | | | '_ \ 
/\__/ /  __/ (__| | | | |_| | |_) |
\____/ \___|\___\_| |_/\__,_|_.__/ Client Version 0.0.0-4bfaf20-20230731134248

WARNING: Desired wait interval (0 s) is too short. Setting it to 1 seconds.
ERROR: The SecHub server responded with HTTP status code '401'
body={"status":401,"error":"Unauthorized","message":"Unauthorized","details":[],"timeStamp":"Mon Jul 31 13:57:31 UTC 2023"}
Hint: Unauthorized - Please check if your SecHub credentials (userID and API-token) are valid.
13:57:31.059 [Time-limited test] DEBUG org.springframework.web.client.RestTemplate - HTTP POST https://localhost:8443/api/anonymous/integrationtest/log/info
13:57:31.059 [Time-limited test] DEBUG org.springframework.web.client.RestTemplate - Accept=[text/plain, application/json, application/cbor, application/*+json, */*]
13:57:31.059 [Time-limited test] DEBUG org.springframework.web.client.RestTemplate - Writing [

End of integration test:
 - Test  : class com.mercedesbenz.sechub.integrationtest.scenario8.ProductExecutorConfigurationScenario8IntTest
 - Method: two_profiles_with_same_config_inside_for_same_product_result_in_scanlog_with_one_metadata_and_result_entry_for_product
 - Time  : 352 ms from start of actual test until end

de-jcup commented 11 months ago

On Server side following happend:

2023-07-31 13:57:30.702 DEBUG 14546 --- [xecutor_thread2] c.m.s.d.a.AuthMessageHandler             : received domain request: DomainMessage [id=USER_ROLES_CHANGED, parameters={user.roles.data={"userId":"s08_0002_user1","roles":["ROLE_OWNER","ROLE_USER"]}}]
2023-07-31 13:57:30.703 DEBUG 14546 --- [xecutor_thread2] c.m.s.d.a.s.AuthUserUpdateRolesService   : Current auth roles of user 's08_0002_user1'. Roles: superadmin=false, user=true, owner=true
2023-07-31 13:57:30.703  INFO 14546 --- [xecutor_thread2] c.m.s.d.a.s.AuthUserUpdateRolesService   : Updated auth roles of user 's08_0002_user1'. Roles: superadmin=false, user=true, owner=true
2023-07-31 13:57:30.702 ERROR 14546 --- [xecutor_thread4] c.m.s.s.messaging.DomainMessageService   : Was not able to run request:DomainMessage [id=USER_API_TOKEN_CHANGED, parameters={user.apitoken.data={"emailAdress":"s08_0002_user1@example.org","userId":"s08_0002_user1","hashedApiToken":"{bcrypt}$2a$10$M/tZ8xpeIu7wA900BVRssO0.mU92QI8QAW5qosGbAatYe8i/S8fX6"}}] with handler com.mercedesbenz.sechub.domain.authorization.AuthMessageHandler@6df11e91

org.springframework.orm.ObjectOptimisticLockingFailureException: Object of class [com.mercedesbenz.sechub.domain.authorization.AuthUser] with identifier [s08_0002_user1]: optimistic locking failed; nested exception is org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [com.mercedesbenz.sechub.domain.authorization.AuthUser#s08_0002_user1]
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.convertHibernateAccessException(HibernateJpaDialect.java:315)
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:233)
    at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(AbstractEntityManagerFactoryBean.java:551)
    at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:61)
    at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:242)
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:152)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:174)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:220)
    at jdk.proxy2/jdk.proxy2.$Proxy214.save(Unknown Source)
    at com.mercedesbenz.sechub.domain.authorization.service.AuthUpdateUserApiTokenService.updateAPIToken(AuthUpdateUserApiTokenService.java:32)
    at com.mercedesbenz.sechub.domain.authorization.AuthMessageHandler.handleUserApiTokenChanged(AuthMessageHandler.java:77)
    at com.mercedesbenz.sechub.domain.authorization.AuthMessageHandler.receiveAsyncMessage(AuthMessageHandler.java:54)
    at com.mercedesbenz.sechub.sharedkernel.messaging.DomainMessageService$AsynchronMessageHandlerTaskAdapter.run(DomainMessageService.java:197)
    at org.springframework.security.concurrent.DelegatingSecurityContextRunnable.run(DelegatingSecurityContextRunnable.java:82)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
    at java.base/java.lang.Thread.run(Thread.java:833)
Caused by: org.hibernate.StaleObjectStateException: Row was updated or deleted by another transaction (or unsaved-value mapping was incorrect) : [com.mercedesbenz.sechub.domain.authorization.AuthUser#s08_0002_user1]
    at org.hibernate.event.internal.DefaultMergeEventListener.entityIsDetached(DefaultMergeEventListener.java:343)
    at org.hibernate.event.internal.DefaultMergeEventListener.onMerge(DefaultMergeEventListener.java:175)
    at org.hibernate.event.internal.DefaultMergeEventListener.onMerge(DefaultMergeEventListener.java:74)
    at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:107)
    at org.hibernate.internal.SessionImpl.fireMerge(SessionImpl.java:829)
    at org.hibernate.internal.SessionImpl.merge(SessionImpl.java:816)
    at jdk.internal.reflect.GeneratedMethodAccessor86.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:315)
    at jdk.proxy2/jdk.proxy2.$Proxy171.merge(Unknown Source)
    at org.springframework.data.jpa.repository.support.SimpleJpaRepository.save(SimpleJpaRepository.java:669)
    at jdk.internal.reflect.GeneratedMethodAccessor68.invoke(Unknown Source)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:568)
    at org.springframework.data.repository.core.support.RepositoryMethodInvoker$RepositoryFragmentMethodInvoker.lambda$new$0(RepositoryMethodInvoker.java:289)
    at org.springframework.data.repository.core.support.RepositoryMethodInvoker.doInvoke(RepositoryMethodInvoker.java:137)
    at org.springframework.data.repository.core.support.RepositoryMethodInvoker.invoke(RepositoryMethodInvoker.java:121)
    at org.springframework.data.repository.core.support.RepositoryComposition$RepositoryFragments.invoke(RepositoryComposition.java:530)
    at org.springframework.data.repository.core.support.RepositoryComposition.invoke(RepositoryComposition.java:286)
    at org.springframework.data.repository.core.support.RepositoryFactorySupport$ImplementationMethodExecutionInterceptor.invoke(RepositoryFactorySupport.java:640)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.doInvoke(QueryExecutorMethodInterceptor.java:164)
    at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.invoke(QueryExecutorMethodInterceptor.java:139)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:81)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:137)
    ... 15 common frames omitted

2023-07-31 13:57:30.703 DEBUG 14546 --- [0.1-8443-exec-1] .s.d.a.p.ProjectDetailInformationService : fetching project details for project:s08_0002project1
2023-07-31 13:57:30.705 DEBUG 14546 --- [0.1-8443-exec-5] c.m.s.d.a.u.UserDetailInformationService : User int-test_superadmin is fetching user details for user: s08_0002_user1
2023-07-31 13:57:30.707  INFO 14546 --- [0.1-8443-exec-2] .s.c.IntegrationTestServerRestController : FROM INTEGRATION-TEST:

  Start of integration test

  - Test class:com.mercedesbenz.sechub.integrationtest.scenario8.ProductExecutorConfigurationScenario8IntTest
  - Method:two_profiles_with_same_config_inside_for_same_product_result_in_scanlog_with_one_metadata_and_result_entry_for_product

2023-07-31 13:57:31.009  INFO 14546 --- [0.1-8443-exec-9] c.m.s.s.logging.AuditLogService          : [AUDIT] (int-test_superadmin) :Wants to create product execution configuration 'exec-config-1', enabled: true for executor:NETSPARKER, V1
2023-07-31 13:57:31.010  INFO 14546 --- [0.1-8443-exec-9] s.p.c.CreateProductExecutorConfigService : Created product execution configuration 'exec-config-1', enabled=true, with uuidD=db9b0e1e-fcbe-42b2-bb83-f9ab7a3267d3 for executor:NETSPARKER, V1
2023-07-31 13:57:31.013  INFO 14546 --- [0.1-8443-exec-8] c.m.s.s.logging.AuditLogService          : [AUDIT] (int-test_superadmin) :Wants to removed product execution profile profile1
2023-07-31 13:57:31.013 DEBUG 14546 --- [0.1-8443-exec-8] p.c.DeleteProductExecutionProfileService : Start removing configurations and project ids from profile:profile1
2023-07-31 13:57:31.014 DEBUG 14546 --- [0.1-8443-exec-8] p.c.DeleteProductExecutionProfileService : Start delete of profile:profile1
2023-07-31 13:57:31.015  INFO 14546 --- [0.1-8443-exec-8] p.c.DeleteProductExecutionProfileService : Removed product execution profile id:profile1, description:null
2023-07-31 13:57:31.018  INFO 14546 --- [0.1-8443-exec-7] c.m.s.s.logging.AuditLogService          : [AUDIT] (int-test_superadmin) :Wants to create product execution profile'profile1'
2023-07-31 13:57:31.018  INFO 14546 --- [0.1-8443-exec-7] p.c.CreateProductExecutionProfileService : Created product execution profile'profile1' 
2023-07-31 13:57:31.023  INFO 14546 --- [0.1-8443-exec-6] c.m.s.s.logging.AuditLogService          : [AUDIT] (int-test_superadmin) :Reads setup for executor configuration:profile1
2023-07-31 13:57:31.025  INFO 14546 --- [.1-8443-exec-10] c.m.s.s.logging.AuditLogService          : [AUDIT] (int-test_superadmin) :Wants to update product execution configuration setup for executor:profile1
2023-07-31 13:57:31.026  INFO 14546 --- [.1-8443-exec-10] p.c.UpdateProductExecutionProfileService : Updated product execution profile profile1
2023-07-31 13:57:31.028  INFO 14546 --- [0.1-8443-exec-3] c.m.s.s.logging.AuditLogService          : [AUDIT] (int-test_superadmin) :Wants to add association between project s08_0002project1 and profile profile1
2023-07-31 13:57:31.028  INFO 14546 --- [0.1-8443-exec-3] p.c.UpdateProductExecutionProfileService : project s08_0002project1 added to profile profile1
2023-07-31 13:57:31.031  INFO 14546 --- [0.1-8443-exec-5] c.m.s.s.logging.AuditLogService          : [AUDIT] (int-test_superadmin) :Wants to create product execution profile'profile2'
2023-07-31 13:57:31.032  INFO 14546 --- [0.1-8443-exec-5] p.c.CreateProductExecutionProfileService : Created product execution profile'profile2' 
2023-07-31 13:57:31.033  INFO 14546 --- [0.1-8443-exec-2] c.m.s.s.logging.AuditLogService          : [AUDIT] (int-test_superadmin) :Reads setup for executor configuration:profile2
2023-07-31 13:57:31.035  INFO 14546 --- [0.1-8443-exec-9] c.m.s.s.logging.AuditLogService          : [AUDIT] (int-test_superadmin) :Wants to update product execution configuration setup for executor:profile2
2023-07-31 13:57:31.036  INFO 14546 --- [0.1-8443-exec-9] p.c.UpdateProductExecutionProfileService : Updated product execution profile profile2
2023-07-31 13:57:31.038  INFO 14546 --- [0.1-8443-exec-4] c.m.s.s.logging.AuditLogService          : [AUDIT] (int-test_superadmin) :Wants to add association between project s08_0002project1 and profile profile2
2023-07-31 13:57:31.038  INFO 14546 --- [0.1-8443-exec-4] p.c.UpdateProductExecutionProfileService : project s08_0002project1 added to profile profile2
2023-07-31 13:57:31.057  WARN 14546 --- [0.1-8443-exec-6] c.m.s.s.l.DefaultSecurityLogService      : [SECURITY] [WRONG USAGE]:
data=
{
  "type" : "WRONG_USAGE",
  "clientIp" : "127.0.0.1",
  "message" : "401 UNAUTHORIZED",
  "requestURI" : "/api/project/s08_0002project1/job",
  "httpHeaders" : {
    "accept" : "application/json",
    "accept-encoding" : "gzip",
    "authorization" : "Basic cz***length:90",
    "content-length" : "114",
    "content-type" : "application/json",
    "host" : "localhost:8443",
    "user-agent" : "Go-http-client/1.1"
  },
  "sessionId" : "EF887D4B4C4C95CB08F9E5E2D124730B"
}
, message=401 UNAUTHORIZED
2023-07-31 13:57:31.057  INFO 14546 --- [0.1-8443-exec-6] c.m.s.server.core.ServerErrorController  : Returning status: 401, message: Unauthorized, details: [], timeStamp: Mon Jul 31 13:57:31 UTC 2023, withTrace: false
2023-07-31 13:57:31.060  INFO 14546 --- [0.1-8443-exec-1] .s.c.IntegrationTestServerRestController : FROM INTEGRATION-TEST:

End of integration test:
 - Test  : class com.mercedesbenz.sechub.integrationtest.scenario8.ProductExecutorConfigurationScenario8IntTest
 - Method: two_profiles_with_same_config_inside_for_same_product_result_in_scanlog_with_one_metadata_and_result_entry_for_product
 - Time  : 352 ms from start of actual test until end

de-jcup commented 11 months ago

After analyzing the data it became clear that the AuthUpdateUserApiTokenService.updateAPIToken() call was not able to update the api token, because of an Optimistic Lock Exception (race condition with other update).

There are multiple problems:

first of all, if the api token update fails the test should fail with something like "I was not able to update token for user:xxx" ==> difficult to solve, because this happens asynchronous in another domain... (auth)
the token update mechanism is not resilient: If an optimistic lock happens it should simply reload the entity and update the token again

mercedes-benz / sechub

Fix flaky ProductExecutorConfigurationScenario8IntTest #2423

Situation

Analyze