Skip to content

Commit 139ed5a

Browse files
de-jcupde-jcup
authored
Merge pull request #3973 from mercedes-benz/feature-3970-improve-log-output-on-pds-job-cancellation
Fix user cancelation bug and improve log output on pds job cancellation
2 parents 959f65d + 78d5744 commit 139ed5a

File tree

17 files changed

+175
-179
lines changed

17 files changed

+175
-179
lines changed

‎sechub-administration/src/main/java/com/mercedesbenz/sechub/domain/administration/autocleanup/IntegrationTestAdministrationRestController.java

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,8 @@
11
// SPDX-License-Identifier: MIT
22
package com.mercedesbenz.sechub.domain.administration.autocleanup;
33

4+
import java.util.List;
5+
46
import org.springframework.beans.factory.annotation.Autowired;
57
import org.springframework.context.annotation.Profile;
68
import org.springframework.http.MediaType;
@@ -9,6 +11,8 @@
911
import org.springframework.web.bind.annotation.RestController;
1012

1113
import com.mercedesbenz.sechub.domain.administration.config.AdministrationConfigService;
14+
import com.mercedesbenz.sechub.domain.administration.job.JobInformation;
15+
import com.mercedesbenz.sechub.domain.administration.job.JobInformationRepository;
1216
import com.mercedesbenz.sechub.sharedkernel.Profiles;
1317
import com.mercedesbenz.sechub.sharedkernel.security.APIConstants;
1418

@@ -26,10 +30,20 @@ public class IntegrationTestAdministrationRestController {
2630
@Autowired
2731
private AdministrationConfigService administrationConfigService;
2832

33+
@Autowired
34+
private JobInformationRepository jobInformationRepository;
35+
2936
@RequestMapping(path = APIConstants.API_ANONYMOUS + "integrationtest/autocleanup/inspection/administration/days", method = RequestMethod.GET, produces = {
3037
MediaType.APPLICATION_JSON_VALUE })
3138
public long fetchScheduleAutoCleanupConfiguredDays() {
3239
return administrationConfigService.getAutoCleanupInDays();
3340
}
3441

42+
@RequestMapping(path = APIConstants.API_ANONYMOUS + "integrationtest/administration/jobinformation", method = RequestMethod.GET, produces = {
43+
MediaType.APPLICATION_JSON_VALUE })
44+
45+
public List<JobInformation> fetchAllJobInformationEntries() {
46+
return jobInformationRepository.findAll();
47+
}
48+
3549
}

‎sechub-administration/src/main/java/com/mercedesbenz/sechub/domain/administration/job/JobAdministrationMessageHandler.java

Lines changed: 10 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -37,6 +37,9 @@ public void receiveAsyncMessage(DomainMessage request) {
3737
LOG.debug("received domain request: {}", request);
3838

3939
switch (messageId) {
40+
case JOB_CREATED:
41+
handleJobCreated(request);
42+
break;
4043
case JOB_STARTED:
4144
handleJobStarted(request);
4245
break;
@@ -76,7 +79,13 @@ private void handleJobCancellationRunning(DomainMessage request) {
7679
@IsReceivingAsyncMessage(MessageID.JOB_STARTED)
7780
private void handleJobStarted(DomainMessage request) {
7881
JobMessage message = request.get(MessageDataKeys.JOB_STARTED_DATA);
79-
createService.createByMessage(message, JobStatus.RUNNING);
82+
createService.createOrUpdateByMessage(message, JobStatus.RUNNING);
83+
}
84+
85+
@IsReceivingAsyncMessage(MessageID.JOB_CREATED)
86+
private void handleJobCreated(DomainMessage request) {
87+
JobMessage message = request.get(MessageDataKeys.JOB_CREATED_DATA);
88+
createService.createOrUpdateByMessage(message, JobStatus.CREATED);
8089
}
8190

8291
@IsReceivingAsyncMessage(MessageID.JOB_DONE)

‎sechub-administration/src/main/java/com/mercedesbenz/sechub/domain/administration/job/JobCancelService.java

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -64,15 +64,15 @@ public void userCancelJob(UUID jobUUID, String userId) {
6464
userInputAssertion.assertIsValidUserId(userId);
6565

6666
auditLogService.log("User {} requested cancellation of job {}", userId, jobUUID);
67-
assertUserAllowedCancelJob(jobUUID, userId);
67+
assertUserIsAllowedToCancelJob(jobUUID, userId);
6868

6969
JobMessage message = buildMessage(jobUUID);
7070

7171
/* trigger event */
7272
informCancelJobRequested(message);
7373
}
7474

75-
private void assertUserAllowedCancelJob(UUID jobUUID, String userId) {
75+
private void assertUserIsAllowedToCancelJob(UUID jobUUID, String userId) {
7676
JobInformation jobInfo = jobInformationRepository.findById(jobUUID).orElseThrow(() -> {
7777
LOG.debug("Job not found: {}", jobUUID);
7878
return new NotFoundException("Job not found: " + jobUUID);

‎sechub-administration/src/main/java/com/mercedesbenz/sechub/domain/administration/job/JobInformationCreateService.java

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@
1313
import com.mercedesbenz.sechub.sharedkernel.Step;
1414
import com.mercedesbenz.sechub.sharedkernel.messaging.JobMessage;
1515
import com.mercedesbenz.sechub.sharedkernel.usecases.job.UseCaseSchedulerStartsJob;
16+
import com.mercedesbenz.sechub.sharedkernel.usecases.user.execute.UseCaseUserCreatesNewJob;
1617
import com.mercedesbenz.sechub.sharedkernel.validation.UserInputAssertion;
1718

1819
@Service
@@ -28,7 +29,8 @@ public class JobInformationCreateService {
2829

2930
@Validated
3031
@UseCaseSchedulerStartsJob(@Step(number = 4, name = "Store admin job info", description = "Fetches event about started job and store info in admin domain."))
31-
public void createByMessage(JobMessage message, JobStatus status) {
32+
@UseCaseUserCreatesNewJob(@Step(number = 3, name = "Store admin job info", description = "Fetches event about created job and store info in admin domain."))
33+
public void createOrUpdateByMessage(JobMessage message, JobStatus status) {
3234
String projectId = message.getProjectId();
3335
UUID jobUUID = message.getJobUUID();
3436

‎sechub-administration/src/test/java/com/mercedesbenz/sechub/domain/administration/job/JobInformationCreateServiceTest.java

Lines changed: 4 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -37,7 +37,7 @@ void beforeEach() {
3737
}
3838

3939
@Test
40-
void createByMessage_no_existing_entity_new_entry_will_be_created_and_saved() {
40+
void createOrUpdateByMessage_no_existing_entity_new_entry_will_be_created_and_saved() {
4141
/* prepare */
4242

4343
when(repository.findById(jobUUID)).thenReturn(Optional.empty());
@@ -53,7 +53,7 @@ void createByMessage_no_existing_entity_new_entry_will_be_created_and_saved() {
5353
JobStatus status = JobStatus.RUNNING;
5454

5555
/* execute */
56-
serviceToTest.createByMessage(message, status);
56+
serviceToTest.createOrUpdateByMessage(message, status);
5757

5858
/* test */
5959
verify(repository).findById(jobUUID);
@@ -74,10 +74,8 @@ void createByMessage_no_existing_entity_new_entry_will_be_created_and_saved() {
7474
}
7575

7676
@Test
77-
void createByMessage_an_existing_entity_entry_will_be_reused_and_saved() {
77+
void createOrUpdateByMessage_an_existing_entity_entry_will_be_reused_and_saved() {
7878
/* prepare */
79-
String configuration = "{ dummy }";
80-
8179
JobInformation existingJobInfo = new JobInformation(jobUUID);
8280
existingJobInfo.version = Integer.valueOf(42);
8381

@@ -94,7 +92,7 @@ void createByMessage_an_existing_entity_entry_will_be_reused_and_saved() {
9492
JobStatus status = JobStatus.RUNNING;
9593

9694
/* execute */
97-
serviceToTest.createByMessage(message, status);
95+
serviceToTest.createOrUpdateByMessage(message, status);
9896

9997
/* test */
10098
verify(repository).findById(jobUUID);

‎sechub-integrationtest/src/main/java/com/mercedesbenz/sechub/integrationtest/api/AssertJobInformationAdministration.java

Lines changed: 53 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,8 +3,13 @@
33

44
import static org.junit.Assert.*;
55

6+
import java.util.List;
67
import java.util.UUID;
78

9+
import com.mercedesbenz.sechub.commons.model.JSONConverter;
10+
import com.mercedesbenz.sechub.domain.administration.job.JobInformation;
11+
import com.mercedesbenz.sechub.domain.administration.job.JobStatus;
12+
813
public class AssertJobInformationAdministration<R> extends AbstractAssert {
914

1015
private static final int DEFAULT_TIMEOUT_MS = 6000;
@@ -83,4 +88,52 @@ public R and() {
8388
}
8489
}
8590

91+
public AssertJobInformationAdministration<R> canFindCreatedJob(UUID jobUUID) {
92+
/*
93+
* this is done different - the productive "listRunningJobs" REST call which is
94+
* used by existing asserts here would not list the CREATED parts! So we
95+
* implement this here special
96+
*/
97+
assertJobFoundAndInStatus(jobUUID, JobStatus.CREATED);
98+
return this;
99+
}
100+
101+
private void assertJobFoundAndInStatus(UUID jobUUID, JobStatus expectedJobStatus) {
102+
TestAPI.executeResilient(() -> {
103+
JobInformation found = tryToFindJobInformation(jobUUID);
104+
if (found == null) {
105+
failWithJobInformationList("Expected status " + expectedJobStatus + " but job information was generally not found for SecHub job:" + jobUUID);
106+
}
107+
JobStatus foundStatus = found.getStatus();
108+
if (!expectedJobStatus.equals(foundStatus)) {
109+
failWithJobInformationList("Expected status " + expectedJobStatus + " but was " + foundStatus + " for SecHub job:" + jobUUID);
110+
}
111+
});
112+
}
113+
114+
private void failWithJobInformationList(String message) {
115+
116+
StringBuilder sb = new StringBuilder();
117+
sb.append(message);
118+
sb.append("\nHere the current job information list:\n");
119+
120+
List<JobInformation> list = TestAPI.fetchAllJobInformationEntriesFromAdministration();
121+
String json = JSONConverter.get().toJSON(list, true);
122+
sb.append(json);
123+
124+
fail(sb.toString());
125+
}
126+
127+
private JobInformation tryToFindJobInformation(UUID jobUUID) {
128+
List<JobInformation> list = TestAPI.fetchAllJobInformationEntriesFromAdministration();
129+
for (JobInformation info : list) {
130+
if (jobUUID.equals(info.getJobUUID())) {
131+
/* found entry */
132+
return info;
133+
}
134+
}
135+
return null;
136+
137+
}
138+
86139
}

‎sechub-integrationtest/src/main/java/com/mercedesbenz/sechub/integrationtest/api/TestAPI.java

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -42,6 +42,7 @@
4242
import com.mercedesbenz.sechub.commons.model.JSONConverter;
4343
import com.mercedesbenz.sechub.commons.model.SecHubMessagesList;
4444
import com.mercedesbenz.sechub.commons.pds.data.PDSJobStatusState;
45+
import com.mercedesbenz.sechub.domain.administration.job.JobInformation;
4546
import com.mercedesbenz.sechub.domain.scan.admin.FullScanData;
4647
import com.mercedesbenz.sechub.domain.scan.project.ScanProjectConfig;
4748
import com.mercedesbenz.sechub.integrationtest.internal.DefaultTestExecutionProfile;
@@ -1729,4 +1730,18 @@ public static void clearAllExistingTemplates() {
17291730
getSuperAdminRestHelper().post(url);
17301731

17311732
}
1733+
1734+
public static List<JobInformation> fetchAllJobInformationEntriesFromAdministration() {
1735+
String url = getURLBuilder().buildIntegrationTestFetchAllJobInformationEntriesFromAdministration();
1736+
String json = getSuperAdminRestHelper().getJSON(url);
1737+
1738+
ObjectMapper mapper = TestJSONHelper.get().getMapper();
1739+
ObjectReader readerForListOf = mapper.readerForListOf(JobInformation.class);
1740+
try {
1741+
return readerForListOf.readValue(json);
1742+
} catch (Exception e) {
1743+
throw new IllegalStateException("was not able to fetch security logs", e);
1744+
}
1745+
}
1746+
17321747
}

‎sechub-integrationtest/src/test/java/com/mercedesbenz/sechub/integrationtest/scenario2/JobScenario2IntTest.java

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -106,7 +106,7 @@ public void a_triggered_job_is_found_in_running_jobs_list_by_admin__when_not_alr
106106
@Test
107107
public void job_list_for_done_job__and_encryption_and_cleanup_are_working() {
108108
/* step 1 : job list entries */
109-
UUID doneJobUUID = assertAlreadyDoneJobIsNotListedInAdminJobList();
109+
UUID doneJobUUID = assertAlreadyDoneJobIsNotListedInRuningJobAdminJobList();
110110
int scheduleDataSizeBeforeRotate = assertEncryptionStatus().domain("schedule").hasData().getDataSize();
111111

112112
/* step 2 : rotate encryption for job */
@@ -168,7 +168,7 @@ private void triggerEncryptionRotationAndAssertEncryptionIsDone(UUID doneJobUUID
168168
/* @formatter:on */
169169
}
170170

171-
private UUID assertAlreadyDoneJobIsNotListedInAdminJobList() {
171+
private UUID assertAlreadyDoneJobIsNotListedInRuningJobAdminJobList() {
172172
/* @formatter:off */
173173
/* prepare */
174174
as(SUPER_ADMIN).assignUserToProject(USER_1, PROJECT_1);
@@ -185,6 +185,9 @@ private UUID assertAlreadyDoneJobIsNotListedInAdminJobList() {
185185
canFindJob(jobUUID).
186186
havingExecutionState(TestExecutionState.INITIALIZING).
187187
and().
188+
onJobAdministration().
189+
canFindCreatedJob(jobUUID).
190+
and().
188191
canApproveJob(PROJECT_1, jobUUID);
189192

190193
assertUser(SUPER_ADMIN).

‎sechub-pds/src/main/java/com/mercedesbenz/sechub/pds/execution/PDSExecutionCallable.java

Lines changed: 28 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -188,6 +188,10 @@ Job output stream (last %s chars):
188188
return result;
189189
}
190190

191+
public UUID getPdsJobUUID() {
192+
return pdsJobUUID;
193+
}
194+
191195
private long calculateTimeToWaitForProductInMinutes() {
192196
ProcessHandlingDataFactory processHandlingDataFactory = serviceCollection.getProcessHandlingDataFactory();
193197
ProductLaunchProcessHandlingData launchProcessdata = processHandlingDataFactory.createForLaunchOperation(config);
@@ -249,7 +253,8 @@ void waitForProcessEndAndGetResultByFiles(PDSExecutionResult result, UUID jobUUI
249253
result.setResult("Product time out.");
250254
result.setExitCode(1);
251255

252-
prepareForCancel(true);
256+
prepareForCancel(true); // here we just reuse cancel operation to ensure process will be terminated same
257+
// way as done for canceling
253258
}
254259

255260
streamDatawatcherRunnable.stop();
@@ -497,15 +502,24 @@ private void createProcess(UUID pdsJobUUID, PDSJobConfiguration config, String p
497502
*/
498503
@UseCaseSystemHandlesJobCancelRequests(@PDSStep(name = "process cancellation", description = "process created by job will be destroyed. If configured, a given time in seconds will be waited, to give the process the chance handle some cleanup and to end itself.", number = 4))
499504
boolean prepareForCancel(boolean mayInterruptIfRunning) {
500-
if (process == null || !process.isAlive()) {
505+
LOG.info("Preparing cancel of PDS job: {}", pdsJobUUID);
506+
507+
if (process == null) {
508+
LOG.info("Skip cancellation of PDS job {} because process was null.", pdsJobUUID);
501509
return true;
502510
}
511+
512+
if (!process.isAlive()) {
513+
LOG.info("Skip cancellation of PDS job {} because process already no longer alive.", pdsJobUUID);
514+
return true;
515+
}
516+
503517
cancelOperationsHasBeenStarted = true;
504518

505519
ProductCancellationProcessHandlingData processHandlingData = null;
506520

507521
if (config == null) {
508-
LOG.warn("No configuration available for job:{}. Cannot create dedicated process handling data. No process wait possible.", pdsJobUUID);
522+
LOG.warn("No configuration available for job: {}. Cannot create dedicated process handling data. No process wait possible.", pdsJobUUID);
509523
} else {
510524
ProcessHandlingDataFactory processHandlingDataFactory = serviceCollection.getProcessHandlingDataFactory();
511525
processHandlingData = processHandlingDataFactory.createForCancelOperation(config);
@@ -541,33 +555,34 @@ private void handleProcessCancellation(ProductCancellationProcessHandlingData pr
541555

542556
if (isWaitOnCancelOperationAccepted(processHandlingData)) {
543557
int millisecondsToWaitForNextCheck = processHandlingData.getMillisecondsToWaitForNextCheck();
544-
LOG.info("Cancel job: {}: give process chance to cancel. Will wait a maximum time of {} seconds. The check intervall is: {} milliseconds",
545-
pdsJobUUID, processHandlingData.getSecondsToWaitForProcess(), millisecondsToWaitForNextCheck);
558+
LOG.info("Cancel PDS job: {}: give process a chance to terminate. Will wait up to {} seconds. The check intervall is {} milliseconds", pdsJobUUID,
559+
processHandlingData.getSecondsToWaitForProcess(), millisecondsToWaitForNextCheck);
546560

547561
while (processHandlingData.isStillWaitingForProcessAccepted()) {
548562
if (process.isAlive()) {
549563
try {
550-
551-
LOG.debug("Cancel job: {}: wait {} milliseconds before next process alive check.", pdsJobUUID, millisecondsToWaitForNextCheck);
564+
LOG.debug("Cancel PDS job: {}: wait {} milliseconds before next process alive check.", pdsJobUUID, millisecondsToWaitForNextCheck);
552565
Thread.sleep(millisecondsToWaitForNextCheck);
553566
} catch (InterruptedException e) {
554567
Thread.currentThread().interrupt();
555568
}
556569
} else {
557-
LOG.info("Process of job: {} is no longer alive", pdsJobUUID);
570+
LOG.info("Cancel PDS job: {}: process is no longer alive", pdsJobUUID);
558571
break;
559572
}
560573
}
561-
LOG.info("Cancel job: {}: waited {} milliseconds at all", pdsJobUUID, System.currentTimeMillis() - processHandlingData.getProcessStartTimeStamp());
574+
LOG.info("Cancel PDS job: {}: waited {} milliseconds", pdsJobUUID, System.currentTimeMillis() - processHandlingData.getProcessStartTimeStamp());
562575

563576
} else {
564-
LOG.info("Cancel job: {}: will not wait.", pdsJobUUID);
577+
LOG.info("Cancel PDS job: {}: will not wait any longer.", pdsJobUUID);
565578
}
579+
580+
/* Ensure process is terminated */
566581
if (process.isAlive()) {
567-
LOG.info("Cancel job: {}: still alive, will destroy underlying process forcibly.", pdsJobUUID);
568-
process.destroyForcibly();
582+
LOG.info("Cancel PDS job: {}: still alive, will terminate underlying process forcibly.", pdsJobUUID);
583+
process.destroyForcibly(); // SIGKILL by JVM
569584
} else {
570-
LOG.info("Cancel job: {}: has terminated itself.", pdsJobUUID);
585+
LOG.info("Cancel PDS job: {}: has terminated itself.", pdsJobUUID);
571586
}
572587
}
573588

‎sechub-pds/src/main/java/com/mercedesbenz/sechub/pds/execution/PDSExecutionFutureTask.java

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,8 @@ public PDSExecutionFutureTask(PDSExecutionCallable callable) {
2929
@Override
3030
public boolean cancel(boolean mayInterruptIfRunning) {
3131

32+
LOG.debug("Task starts cancellation of PDS job: {}, ", execCallable.getPdsJobUUID());
33+
3234
boolean processHasTerminated = execCallable.prepareForCancel(mayInterruptIfRunning);
3335
boolean superImplementation = super.cancel(mayInterruptIfRunning);
3436

0 commit comments

Comments
 (0)