mercedes-benz / sechub

SecHub provides a central API to test software with different security tools.
https://mercedes-benz.github.io/sechub/
MIT License
263 stars 63 forks source link

Role recalculation problems, potential race conditions on projec #120

Closed de-jcup closed 4 years ago

de-jcup commented 4 years ago

Description

ProjectDeleteScenario3IntTest#super_admin_deletes_project__deletes_also_access_entries_other_domains_and_user_rolecalculation_is_done Line :58 fails on integration tests.

This is something that happens very often at GitHub Actions, but very seldom at Jenkins or local machines.

At the beginning I thought it was just a flaky test and the reason would be only because of taking too much time until event was handled and test just not waited enough time. But... looking into the logs there seems to be something wrong (maybe a race condition) at project delete:

Local (test working):

2019-12-14 13:50:47.930  INFO 4145 --- [nio-8443-exec-4] c.d.s.s.logging.AuditLogService          : [AUDIT] (int-test_superadmin) :triggers delete of project scenario3_project1
2019-12-14 13:50:47.972 DEBUG 4145 --- [xecutor_thread4] c.d.s.d.schedule.ScheduleMessageHandler  : received domain request: DomainMessage [id=PROJECT_DELETED, parameters={environment.base.url=https://localhost:8443, project.delete.data={"whitelist":[],"projectId":"scenario3_project1","projectOwnerEmailAddress":"scenario3_user1@example.org","userEmailAdresses":["scenario3_user1@example.org"],"projectActionTriggeredBy":"int-test_superadmin"}}]
2019-12-14 13:50:47.982 DEBUG 4145 --- [xecutor_thread2] c.d.s.d.n.NotificationMessageHandler     : received domain request: DomainMessage [id=PROJECT_DELETED, parameters={environment.base.url=https://localhost:8443, project.delete.data={"whitelist":[],"projectId":"scenario3_project1","projectOwnerEmailAddress":"scenario3_user1@example.org","userEmailAdresses":["scenario3_user1@example.org"],"projectActionTriggeredBy":"int-test_superadmin"}}]
2019-12-14 13:50:47.983  INFO 4145 --- [xecutor_thread2] c.d.s.d.n.email.MockEmailService         : resolved messages:1 for user:sechub@example.org
2019-12-14 13:50:47.983  INFO 4145 --- [xecutor_thread2] c.d.s.d.n.email.MockEmailService         : Send TO target:sechub@example.org [ 2 ]: subject:'SecHub Project scenario3_project1 has been deleted', 
2019-12-14 13:50:47.984  INFO 4145 --- [xecutor_thread2] c.d.s.d.n.email.MockEmailService         : resolved messages:2 for user:scenario3_user1@example.org
2019-12-14 13:50:47.984  INFO 4145 --- [xecutor_thread2] c.d.s.d.n.email.MockEmailService         : Send TO target:scenario3_user1@example.org [ 3 ]: subject:'A SecHub project you were the owner was deleted', 
2019-12-14 13:50:47.984  INFO 4145 --- [xecutor_thread2] c.d.s.d.n.email.MockEmailService         : resolved messages:3 for user:scenario3_user1@example.org
2019-12-14 13:50:47.984  INFO 4145 --- [xecutor_thread2] c.d.s.d.n.email.MockEmailService         : Send BCC target:scenario3_user1@example.org [ 4 ]: subject:'A SecHub project where you have been a user was deleted', 
2019-12-14 13:50:47.989 DEBUG 4145 --- [xecutor_thread1] c.d.s.domain.scan.ScanMessageHandler     : received domain request: DomainMessage [id=PROJECT_DELETED, parameters={environment.base.url=https://localhost:8443, project.delete.data={"whitelist":[],"projectId":"scenario3_project1","projectOwnerEmailAddress":"scenario3_user1@example.org","userEmailAdresses":["scenario3_user1@example.org"],"projectActionTriggeredBy":"int-test_superadmin"}}]
2019-12-14 13:50:47.993 DEBUG 4145 --- [xecutor_thread3] a.u.UserRoleAdministrationMessageHandler : received domain request: DomainMessage [id=REQUEST_USER_ROLE_RECALCULATION, parameters={user.name={"userId":"scenario3_user1"}}]
2019-12-14 13:50:48.009  INFO 4145 --- [xecutor_thread4] s.a.ScheduleDeleteAllProjectAcessService : Removed any access entry for project:scenario3_project1
2019-12-14 13:50:48.010  INFO 4145 --- [xecutor_thread1] ScanDeleteAnyAccessToProjectAtAllService : Deleted any access at all for project:scenario3_project1
2019-12-14 13:50:48.013 DEBUG 4145 --- [xecutor_thread3] c.d.s.d.a.AuthMessageHandler             : received domain request: DomainMessage [id=USER_ROLES_CHANGED, parameters={user.roles.data={"userId":"scenario3_user1","roles":["ROLE_USER"]}}]
2019-12-14 13:50:48.025 DEBUG 4145 --- [xecutor_thread3] c.d.s.d.a.s.AuthUserUpdateRolesService   : Current auth roles of user 'scenario3_user1'. Roles: superadmin=false, user=true, owner=true
2019-12-14 13:50:48.025  INFO 4145 --- [xecutor_thread3] c.d.s.d.a.s.AuthUserUpdateRolesService   : Updated auth roles of user 'scenario3_user1'. Roles: superadmin=false, user=true, owner=false
2019-12-14 13:50:48.037  INFO 4145 --- [xecutor_thread1] c.d.s.d.scan.ProjectDataDeleteService    : Deleted all data (results,reports, scanlogs) for project:scenario3_project1
2019-12-14 13:50:50.028 DEBUG 4145 --- [nio-8443-exec-7] .s.d.a.p.ProjectDetailInformationService : fetching project details for project:scenario3_project1
2019-12-14 13:50:50.106 DEBUG 4145 --- [nio-8443-exec-9] c.d.s.d.a.u.UserDetailInformationService : User int-test_superadmin is fetching user details for user:scenario3_user1
2019-12-14 13:50:50.388  INFO 4145 --- [nio-8443-exec-1] .s.s.IntegrationTestServerRestController : Integration test server says user 'scenario3_user1' has allowed role 'ROLE_USER' - all authorities: 'ROLE_USER'

GitHub Actions build (test failed):

2019-12-14 00:54:57.094  INFO 7237 --- [nio-8443-exec-3] c.d.s.s.logging.AuditLogService          : [AUDIT] (int-test_superadmin) :triggers delete of project scenario3_project1
2019-12-14 00:54:57.098 DEBUG 7237 --- [xecutor_thread2] c.d.s.d.schedule.ScheduleMessageHandler  : received domain request: DomainMessage [id=PROJECT_DELETED, parameters={environment.base.url=https://localhost:8443, project.delete.data={"whitelist":[],"projectId":"scenario3_project1","projectOwnerEmailAddress":"scenario3_user1@example.org","userEmailAdresses":["scenario3_user1@example.org"],"projectActionTriggeredBy":"int-test_superadmin"}}]
2019-12-14 00:54:57.098  INFO 7237 --- [xecutor_thread2] s.a.ScheduleDeleteAllProjectAcessService : Removed any access entry for project:scenario3_project1
2019-12-14 00:54:57.098 DEBUG 7237 --- [xecutor_thread3] c.d.s.d.n.NotificationMessageHandler     : received domain request: DomainMessage [id=PROJECT_DELETED, parameters={environment.base.url=https://localhost:8443, project.delete.data={"whitelist":[],"projectId":"scenario3_project1","projectOwnerEmailAddress":"scenario3_user1@example.org","userEmailAdresses":["scenario3_user1@example.org"],"projectActionTriggeredBy":"int-test_superadmin"}}]
2019-12-14 00:54:57.099  INFO 7237 --- [xecutor_thread3] c.d.s.d.n.email.MockEmailService         : resolved messages:2 for user:sechub@example.org
2019-12-14 00:54:57.099  INFO 7237 --- [xecutor_thread3] c.d.s.d.n.email.MockEmailService         : Send TO target:sechub@example.org [ 3 ]: subject:'SecHub Project scenario3_project1 has been deleted', 
2019-12-14 00:54:57.099  INFO 7237 --- [xecutor_thread3] c.d.s.d.n.email.MockEmailService         : resolved messages:5 for user:scenario3_user1@example.org
2019-12-14 00:54:57.099  INFO 7237 --- [xecutor_thread3] c.d.s.d.n.email.MockEmailService         : Send TO target:scenario3_user1@example.org [ 6 ]: subject:'A SecHub project you were the owner was deleted', 
2019-12-14 00:54:57.099  INFO 7237 --- [xecutor_thread3] c.d.s.d.n.email.MockEmailService         : resolved messages:6 for user:scenario3_user1@example.org
2019-12-14 00:54:57.099  INFO 7237 --- [xecutor_thread3] c.d.s.d.n.email.MockEmailService         : Send BCC target:scenario3_user1@example.org [ 7 ]: subject:'A SecHub project where you have been a user was deleted', 
2019-12-14 00:54:57.099 DEBUG 7237 --- [xecutor_thread1] c.d.s.domain.scan.ScanMessageHandler     : received domain request: DomainMessage [id=PROJECT_DELETED, parameters={environment.base.url=https://localhost:8443, project.delete.data={"whitelist":[],"projectId":"scenario3_project1","projectOwnerEmailAddress":"scenario3_user1@example.org","userEmailAdresses":["scenario3_user1@example.org"],"projectActionTriggeredBy":"int-test_superadmin"}}]
2019-12-14 00:54:57.099  INFO 7237 --- [xecutor_thread1] ScanDeleteAnyAccessToProjectAtAllService : Deleted any access at all for project:scenario3_project1
2019-12-14 00:54:57.100  INFO 7237 --- [xecutor_thread1] c.d.s.d.scan.ProjectDataDeleteService    : Deleted all data (results,reports, scanlogs) for project:scenario3_project1
2019-12-14 00:54:57.100 DEBUG 7237 --- [xecutor_thread4] a.u.UserRoleAdministrationMessageHandler : received domain request: DomainMessage [id=REQUEST_USER_ROLE_RECALCULATION, parameters={user.name={"userId":"scenario3_user1"}}]
2019-12-14 00:54:57.102 DEBUG 7237 --- [xecutor_thread4] c.d.s.d.a.AuthMessageHandler             : received domain request: DomainMessage [id=USER_ROLES_CHANGED, parameters={user.roles.data={"userId":"scenario3_user1","roles":["ROLE_OWNER","ROLE_USER"]}}]
2019-12-14 00:54:57.102 DEBUG 7237 --- [xecutor_thread4] c.d.s.d.a.s.AuthUserUpdateRolesService   : Current auth roles of user 'scenario3_user1'. Roles: superadmin=false, user=true, owner=true
2019-12-14 00:54:57.102  INFO 7237 --- [xecutor_thread4] c.d.s.d.a.s.AuthUserUpdateRolesService   : Updated auth roles of user 'scenario3_user1'. Roles: superadmin=false, user=true, owner=true
2019-12-14 00:54:59.108 DEBUG 7237 --- [nio-8443-exec-4] .s.d.a.p.ProjectDetailInformationService : fetching project details for project:scenario3_project1
2019-12-14 00:54:59.125 DEBUG 7237 --- [nio-8443-exec-4] c.d.s.d.a.u.UserDetailInformationService : User int-test_superadmin is fetching user details for user:scenario3_user1
2019-12-14 00:54:59.237  INFO 7237 --- [nio-8443-exec-6] .s.s.IntegrationTestServerRestController : Integration test server says user 'scenario3_user1' has allowed role 'ROLE_OWNER' - all authorities: 'ROLE_OWNER ROLE_USER'

TODO

At the moment this seems to happen only at a project delete actions. And role "owner" is not really used at the moment . It has no influences to user or administrator role So it's currently not having so much impact - means no hotfix release but just in next one.

But we must analyse why this happens.

de-jcup commented 4 years ago

Analyse result

Whenever you got something like

package com.daimler.sechub.domainA;

class ServiceX{
   @IsSendingAsynchronousEvent(EVENT_ID1)
   @Transactional
   public void myServiceMethod(){
       repositoryA.changePersistedData();
       ...
       eventBus.sendEvent(EVENT_ID1);
   }
}

package com.daimler.sechub.domainA;

class ServiceY{

  @IsReceivingAsynchronousEvent(EVENT_ID1)
  public void receiveEvent1(){
           Data d = repositoryA.loadPotentialChangedPersistedData();
           doSomethingDependendingOn(d);
  }
}

This can reach to race conditions!

Reason: The transaction in ServiceX has not yet finished while asynchronous event is triggered and will run. When the event is handled fast enough in ServiceY it can happen that the transaction in ServiceX was not finished and we load old state in ServiceY.

This is an odd situation not only in delete but also in any situation where the event is processed in same domain as it was started (because data is not inside event but is reloaded from same database/table and so can have race conditions)

For this reason, I have to revise my previous assessment and create a new milestone + release 0.13.1 that contains the hotfix.

de-jcup commented 4 years ago

General Solution


package com.daimler.sechub.domainA;

@AutoWired
ServiceTransactionalX serviceTransactional;

class ServiceX{
   @IsSendingAsynchronousEvent(EVENT_ID1)
    public void myServiceMethod(){
        serviceTransactional.myTransactionalServiceMethod()l;
        eventBus.sendEvent(EVENT_ID1);
   }
}

package com.daimler.sechub.domainA;
class ServiceTransactionalX{
   @Transactional
   public void myTransactionalServiceMethod(){
        repositoryA.changePersistedData();
   }
}

package com.daimler.sechub.domainA;

class ServiceY{

  @IsReceivingAsynchronousEvent(EVENT_ID1)
  public void receiveEvent1(){
           Data d = repositoryA.loadPotentialChangedPersistedData();
           doSomethingDependendingOn(d);
  }
}