search

mercedes-benz / sechub

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

Fix flaky test `ProjectChangeAccessLevelScenario3IntTest` #803

Closed de-jcup closed 3 years ago

de-jcup commented 3 years ago

Situation

ProjectChangeAccessLevelScenario3IntTest does sometimes fail. It expects a YELLOW result but receives a GREEN result instead

Wanted

No more flaky...

Solution

Inspect the problem and fix the test

de-jcup commented 3 years ago

Inspection of a failing build

This comment contains all necessary information. The next comment will contain only reduced parts.

Info

SecHub job: c76eaf76-11ea-43f7-bc06-cbda49ed4e66

Console-Log parts

 _____           _   _       _     
/  ___|         | | | |     | |    
\ `--.  ___  ___| |_| |_   _| |__  
 `--. \/ _ \/ __|  _  | | | | '_ \ 
/\__/ /  __/ (__| | | | |_| | |_) |
\____/ \___|\___\_| |_/\__,_|_.__/ Client Version 0.0.0-798d1f1-20210927140803

2021-09-27 14:14:38 (Z) Creating new sechub job
2021-09-27 14:14:38 (Z) Zipping folder: ../sechub-doc/src/main/java (/home/runner/work/sechub/sechub/sechub-integrationtest/build/sechub/example/sechub-doc/src/main/java)
2021-09-27 14:14:38 (Z) Uploading source zip file
2021-09-27 14:14:38 (Z) Approve sechub job
2021-09-27 14:14:39 (Z) Waiting for job c76eaf76-11ea-43f7-bc06-cbda49ed4e66 to be done

2021-09-27 14:14:39 (Z) Fetching result (format=json) for job c76eaf76-11ea-43f7-bc06-cbda49ed4e66
2021-09-27 14:14:39 (Z) SecHub report written to /tmp/with-sechub-client-9203597355011771097/sechub_report_s03_0009project1_c76eaf76-11ea-43f7-bc06-cbda49ed4e66.json
  GREEN - no severe security vulnerabilities identified
14:14:39.234 [Time-limited test] INFO com.daimler.sechub.integrationtest.api.AssertSecHubReport - --------------------------------------------------------------------------------------------------------
14:14:39.234 [Time-limited test] INFO com.daimler.sechub.integrationtest.api.AssertSecHubReport - -------------------------------------------------- DUMP -----------------------------------------------
14:14:39.234 [Time-limited test] INFO com.daimler.sechub.integrationtest.api.AssertSecHubReport - --------------------------------------------------------------------------------------------------------
14:14:39.241 [Time-limited test] INFO com.daimler.sechub.integrationtest.api.AssertSecHubReport - {
  "jobUUID" : "c76eaf76-11ea-43f7-bc06-cbda49ed4e66",
  "result" : {
    "count" : 0,
    "findings" : [ ]
  },
  "trafficLight" : "GREEN"
}
14:14:39.241 [Time-limited test] INFO com.daimler.sechub.integrationtest.api.AssertSecHubReport - --------------------------------------------------------------------------------------------------------
14:14:39.241 [Time-limited test] INFO com.daimler.sechub.integrationtest.api.AssertSecHubReport - Last ouptput line was:  GREEN - no severe security vulnerabilities identified
14:14:39.241 [Time-limited test] DEBUG org.springframework.web.client.RestTemplate - HTTP POST https://localhost:8443/api/anonymous/integrationtest/log/info
14:14:39.247 [Time-limited test] DEBUG org.springframework.web.client.RestTemplate - Accept=[text/plain, application/json, application/cbor, application/*+json, */*]
14:14:39.247 [Time-limited test] DEBUG org.springframework.web.client.RestTemplate - Writing [

End of integration test:
 - Test class: com.daimler.sechub.integrationtest.scenario3.ProjectChangeAccessLevelScenario3IntTest
 - Method:a_delete_removes_former_access_level_settings

] as "text/plain"
14:1

SecHub server log

2021-09-27 14:14:38.776  INFO 9264 --- [0.1-8443-exec-7] c.d.s.d.s.SchedulerCreateJobService      : New job added:__[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__
2021-09-27 14:14:38.887  INFO 9264 --- [0.1-8443-exec-7] c.d.s.s.logging.AuditLogService          : [AUDIT] (s03_0009_user1) :Wants to upload source code to project s03_0009project1, __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__
2021-09-27 14:14:38.890  INFO 9264 --- [0.1-8443-exec-7] c.d.s.s.s.spring.SharedVolumeJobStorage  : job:c76eaf76-11ea-43f7-bc06-cbda49ed4e66: storing sourcecode.zip in path jobstorage/s03_0009project1
2021-09-27 14:14:38.890 DEBUG 9264 --- [0.1-8443-exec-7] c.d.s.s.s.spring.SharedVolumeJobStorage  : Stored:sourcecode.zip at /tmp/sechub-inttest1055416738326267997/jobstorage/s03_0009project1/c76eaf76-11ea-43f7-bc06-cbda49ed4e66/sourcecode.zip
2021-09-27 14:14:38.891  INFO 9264 --- [0.1-8443-exec-7] c.d.s.s.s.spring.SharedVolumeJobStorage  : job:c76eaf76-11ea-43f7-bc06-cbda49ed4e66: storing sourcecode.zip.checksum in path jobstorage/s03_0009project1
2021-09-27 14:14:38.891 DEBUG 9264 --- [0.1-8443-exec-7] c.d.s.s.s.spring.SharedVolumeJobStorage  : Stored:sourcecode.zip.checksum at /tmp/sechub-inttest1055416738326267997/jobstorage/s03_0009project1/c76eaf76-11ea-43f7-bc06-cbda49ed4e66/sourcecode.zip.checksum
2021-09-27 14:14:38.891  INFO 9264 --- [0.1-8443-exec-7] c.d.s.d.schedule.SchedulerUploadService  : uploaded sourcecode for __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__
2021-09-27 14:14:39.000  INFO 9264 --- [0.1-8443-exec-2] c.d.s.d.s.SchedulerApproveJobService     : job c76eaf76-11ea-43f7-bc06-cbda49ed4e66 now approved
2021-09-27 14:14:39.016 DEBUG 9264 --- [   scheduling-1] c.d.s.d.s.ScheduleJobLauncherService     : Execute job:c76eaf76-11ea-43f7-bc06-cbda49ed4e66
2021-09-27 14:14:39.016 DEBUG 9264 --- [   scheduling-1] c.d.s.d.s.ScheduleJobLauncherService     : Trigger batch job launch :c76eaf76-11ea-43f7-bc06-cbda49ed4e66
2021-09-27 14:14:39.016  INFO 9264 --- [   scheduling-1] c.d.s.d.schedule.batch.AsyncJobLauncher  : async run of job :executeScan
2021-09-27 14:14:39.024 DEBUG 9264 --- [   scheduling-1] c.d.s.d.s.ScheduleJobLauncherService     : Execution triggered: c76eaf76-11ea-43f7-bc06-cbda49ed4e66 has batch-ID:23
2021-09-27 14:14:39.024 DEBUG 9264 --- [   scheduling-1] s.m.IntegrationTestEventInspectorService : inspection id:37
2021-09-27 14:14:39.025 DEBUG 9264 --- [xecutor_thread1] .s.d.a.j.JobAdministrationMessageHandler : received domain request: DomainMessage [id=JOB_STARTED, parameters={job.started.data={"jobUUID":"c76eaf76-11ea-43f7-bc06-cbda49ed4e66","projectId":"s03_0009project1","owner":"s03_0009_user1","configuration":"{\"codeScan\":{\"fileSystem\":{\"folders\":[\"../sechub-doc/src/main/java\"]}},\"apiVersion\":\"1.0\",\"projectId\":\"s03_0009project1\"}","since":"2021/09/27 14:14:39"}}]
2021-09-27 14:14:39.025 DEBUG 9264 --- [xecutor_thread1] c.d.s.d.a.j.JobInformationCreateService  : creating a new job information entry for project=s03_0009project1, job=c76eaf76-11ea-43f7-bc06-cbda49ed4e66
2021-09-27 14:14:39.025 DEBUG 9264 --- [xecutor_thread1] c.d.s.d.a.j.JobInformationCreateService  : saved new job information entry uuid=s03_0009project1 - for project=c76eaf76-11ea-43f7-bc06-cbda49ed4e66, job=b72db568-e340-4989-90cb-51354c4e8f06, 
2021-09-27 14:14:39.034 DEBUG 9264 --- [-job-launcher23] c.d.s.d.s.batch.ScanExecutionTasklet     : executing with parameters:{batch.sechub.uuid=c76eaf76-11ea-43f7-bc06-cbda49ed4e66, random=d0521ab9-4f63-42c2-befa-145ae85306e4}
2021-09-27 14:14:39.041  INFO 9264 --- [06-cbda49ed4e66] c.d.s.d.s.b.SynchronSecHubJobExecutor    : Executing sechub job: c76eaf76-11ea-43f7-bc06-cbda49ed4e66
2021-09-27 14:14:39.042 DEBUG 9264 --- [06-cbda49ed4e66] s.m.IntegrationTestEventInspectorService : inspection id:38
2021-09-27 14:14:39.042  INFO 9264 --- [06-cbda49ed4e66] c.d.sechub.domain.scan.ScanService       : start scan for __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__
2021-09-27 14:14:39.054 DEBUG 9264 --- [06-cbda49ed4e66] c.d.s.d.s.IntegrationTestScanJobListener : registered job:c76eaf76-11ea-43f7-bc06-cbda49ed4e66
2021-09-27 14:14:39.054 DEBUG 9264 --- [06-cbda49ed4e66] c.d.sechub.domain.scan.ScanJobExecutor   : will wait max 3000 milliseconds before cancel checks - job thread is:SecHub-exec-c76eaf76-11ea-43f7-bc06-cbda49ed4e66-23
2021-09-27 14:14:39.054 DEBUG 9264 --- [cbda49ed4e66-23] .s.p.CodeScanProductExecutionServiceImpl : Code scan options found __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__
2021-09-27 14:14:39.054 DEBUG 9264 --- [cbda49ed4e66-23] .s.d.s.p.AbstractProductExecutionService : search config for project=s03_0009project1, executor=CHECKMARX, version=1
2021-09-27 14:14:39.055 DEBUG 9264 --- [cbda49ed4e66-23] .s.d.s.p.AbstractProductExecutionService : no config found for project=s03_0009project1 so skipping executor=CHECKMARX, version=1
2021-09-27 14:14:39.055 DEBUG 9264 --- [cbda49ed4e66-23] .s.d.s.p.AbstractProductExecutionService : search config for project=s03_0009project1, executor=PDS_CODESCAN, version=1
2021-09-27 14:14:39.055 DEBUG 9264 --- [cbda49ed4e66-23] .s.d.s.p.AbstractProductExecutionService : no config found for project=s03_0009project1 so skipping executor=PDS_CODESCAN, version=1
2021-09-27 14:14:39.055 DEBUG 9264 --- [cbda49ed4e66-23] d.s.p.WebScanProductExecutionServiceImpl : No webscan options found for __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__
2021-09-27 14:14:39.055 DEBUG 9264 --- [cbda49ed4e66-23] .s.d.s.p.AbstractProductExecutionService : __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__ NO execution necessary by WebScanProductExecutionServiceImpl
2021-09-27 14:14:39.055 DEBUG 9264 --- [cbda49ed4e66-23] structureScanProductExecutionServiceImpl : No infrastructure options found for __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__
2021-09-27 14:14:39.055 DEBUG 9264 --- [cbda49ed4e66-23] .s.d.s.p.AbstractProductExecutionService : __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__ NO execution necessary by InfrastructureScanProductExecutionServiceImpl
2021-09-27 14:14:39.055 DEBUG 9264 --- [06-cbda49ed4e66] s.m.IntegrationTestEventInspectorService : inspection id:39
2021-09-27 14:14:39.057 DEBUG 9264 --- [06-cbda49ed4e66] c.d.s.d.s.IntegrationTestScanJobListener : unregistered job:c76eaf76-11ea-43f7-bc06-cbda49ed4e66
2021-09-27 14:14:39.058  INFO 9264 --- [06-cbda49ed4e66] c.d.s.d.s.r.CreateScanReportService      : Creating report for __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__, will delete former reports if existing
2021-09-27 14:14:39.059 DEBUG 9264 --- [06-cbda49ed4e66] .s.d.s.p.AbstractProductExecutionService : search config for project=s03_0009project1, executor=SERECO, version=1
2021-09-27 14:14:39.059 DEBUG 9264 --- [06-cbda49ed4e66] .s.d.s.p.AbstractProductExecutionService : no config found for project=s03_0009project1 so skipping executor=SERECO, version=1
2021-09-27 14:14:39.059 DEBUG 9264 --- [06-cbda49ed4e66] .s.d.s.p.AbstractProductExecutionService : no dedicated configuration for report execution was executed before, so fallback to sereco default behaviour
2021-09-27 14:14:39.060  INFO 9264 --- [06-cbda49ed4e66] .s.d.s.p.AbstractProductExecutionService : Start executor:SERECO config:null and wait for result. __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__
2021-09-27 14:14:39.060 DEBUG 9264 --- [06-cbda49ed4e66] .d.s.d.s.p.s.SerecoReportProductExecutor : __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__ start sereco execution
2021-09-27 14:14:39.060  WARN 9264 --- [06-cbda49ed4e66] .d.s.d.s.p.s.SerecoReportProductExecutor : __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__ no product results for [NESSUS, NETSPARKER, CHECKMARX, PDS_CODESCAN, PDS_WEBSCAN, PDS_INFRASCAN] found, will return an empty sereco JSON as result! 
2021-09-27 14:14:39.061 DEBUG 9264 --- [06-cbda49ed4e66] .s.d.s.p.ProductResultTransactionService : persisting result of product SERECO  , config uuid null - traceLogId:com.daimler.sechub.domain.scan.product.ProductResult@1f
de-jcup commented 3 years ago

Analyse

The shrinked, relevant server output:

c.d.sechub.domain.scan.ScanService       : start scan for __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__
c.d.s.d.s.IntegrationTestScanJobListener : registered job:c76eaf76-11ea-43f7-bc06-cbda49ed4e66
.s.p.CodeScanProductExecutionServiceImpl : Code scan options found __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__
.s.d.s.p.AbstractProductExecutionService : search config for project=s03_0009project1, executor=CHECKMARX, version=1
.s.d.s.p.AbstractProductExecutionService : no config found for project=s03_0009project1 so skipping executor=CHECKMARX, version=1
.s.d.s.p.AbstractProductExecutionService : search config for project=s03_0009project1, executor=PDS_CODESCAN, version=1
.s.d.s.p.AbstractProductExecutionService : no config found for project=s03_0009project1 so skipping executor=PDS_CODESCAN, version=1
s.m.IntegrationTestEventInspectorService : inspection id:39
c.d.s.d.s.IntegrationTestScanJobListener : unregistered job:c76eaf76-11ea-43f7-bc06-cbda49ed4e66
c.d.s.d.s.r.CreateScanReportService      : Creating report for __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__, will delete former reports if existing
.s.d.s.p.AbstractProductExecutionService : search config for project=s03_0009project1, executor=SERECO, version=1
.s.d.s.p.AbstractProductExecutionService : no config found for project=s03_0009project1 so skipping executor=SERECO, version=1
.s.d.s.p.AbstractProductExecutionService : no dedicated configuration for report execution was executed before, so fallback to sereco default behaviour
.s.d.s.p.AbstractProductExecutionService : Start executor:SERECO config:null and wait for result. __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__
.d.s.d.s.p.s.SerecoReportProductExecutor : __[SECHUB-UID:c76eaf76-11ea-43f7-bc06-cbda49ed4e66]__ no product results for [NESSUS, NETSPARKER, CHECKMARX, PDS_CODESCAN, PDS_WEBSCAN, PDS_INFRASCAN] found, will return an empty sereco JSON as result!

So... AbstractProductExecutionService#runOnAllAvailableExecutors() logs out it does not find any product executor config for the project!

So this means, at this time, there is NO executor configuration available for the project!

How can this happen?

The test does delete PROJECT_1 per REST API and then directly recreate the project. This happens parallel, so the sometimes recreation can have a a race condition with the delete...