POST webhook is sent before scan is completed. Creating a deadlock on Jenkins builds

  • versions used
    SonarQube - 7.9.1 - build 27448
    Scanner - org.codehaus.mojo:sonar-maven-plugin:3.7.0.1746
    Plugin Jenkins - 2.11 - https://plugins.jenkins.io/sonar/
  • error observed
    sonar scan start + and the SonarQube server send post webbook before the scan is completed
    this issue is related with the post-step github decoration.
https://****-sonarqube/api/ce/task?id=AXWTq0nKzIDHJBORNEiF
{
"task": {
"id": "AXWTq0nKzIDHJBORNEiF",
"type": "REPORT",
"componentId": "AXWTWCHOzIDHJBORNEhi",
"componentKey": "dprep-plugin-sample",
"componentName": "dprep-plugin-sample",
"componentQualifier": "TRK",
"analysisId": "AXWTq0rCohyalsuaF5Bt",
"status": "SUCCESS",
"submittedAt": "2020-11-04T14:31:17+0000",
"submitterLogin": "jenkins",
"startedAt": "2020-11-04T14:31:17+0000",
"executedAt": "2020-11-04T14:34:12+0000",
"executionTimeMs": 174308,
"logs": false,
"hasScannerContext": true,
"organization": "default-organization",
"pullRequest": "2",
"warningCount": 0,
"warnings": []
}
}

Time diff between
sonarqube service task end
"executedAt": “2020-11-04T14:34:12+0000”,
and POST arrived to Jenkins
Nov 04, 2020 2:31:18 PM

Jenkins Logs for the same task ID:

Nov 04, 2020 2:31:18 PM INFO org.sonarsource.scanner.jenkins.pipeline.SonarQubeWebHook doIndex
Received POST from 127.0.0.1
Nov 04, 2020 2:31:18 PM FINE org.sonarsource.scanner.jenkins.pipeline.SonarQubeWebHook
Full details of the POST was {"serverUrl":"https://****-sonarqube","taskId":"AXWTq0nKzIDHJBORNEiF","status":"SUCCESS","analysedAt":"2020-11-04T14:31:13+0000","revision":"712c49228cda1ca6aceded78051d5deb2fa8d98f","changedAt":"2020-11-04T14:31:13+0000","project":{"key":"dprep-plugin-sample","name":"dprep-plugin-sample","url":"https://****/dashboard?id=dprep-plugin-sample"},"branch":{"name":"2","type":"PULL_REQUEST","isMain":false,"url":"https:/***/dashboard?id=dprep-plugin-sample&pullRequest=2"},"qualityGate":{"name":"QA Sonar way","status":"OK","conditions":[{"metric":"new_reliability_rating","operator":"GREATER_THAN","value":"1","status":"OK","errorThreshold":"1"},{"metric":"new_security_rating","operator":"GREATER_THAN","value":"1","status":"OK","errorThreshold":"1"},{"metric":"new_maintainability_rating","operator":"GREATER_THAN","value":"1","status":"OK","errorThreshold":"1"},{"metric":"new_duplicated_lines_density","operator":"GREATER_THAN","status":"NO_VALUE","errorThreshold":"3"}]},"properties":{}}
  • steps to reproduce
    Jenkins sonar scan with the waitForQualityGate step
    the scan need to have a “PullRequestPostAnalysisTask” like github decoration
    basically the
    [o.s.s.w.WebHooksImpl] Sent webhook will be send before the scan is done
  • potential workaround
    For me I can use a sleep step of 5 min ( because my sonar analysis can take a wile to run )

Solution should be or ignore PostAnalysisTask for scan completion or only send the webhook after all the PostAnalysisTasks…

A different task id runner in trace log level ( check the POST sent and the time where the task end )

2020.11.04 14:02:44 INFO  ce[AXWTkSH0zIDHJBORNEh7][o.s.c.t.s.ComputationStepExecutor] Trigger refresh of Portfolios and Applications | status=SUCCESS | time=0ms
2020.11.04 14:02:44 TRACE ce[AXWTkSH0zIDHJBORNEh7][sql] time=1ms | sql=SELECT p.id, p.organization_uuid as organizationUuid, p.uuid as uuid, p.uuid_path as uuidPath, p.project_uuid as projectUuid, p.module_uuid as moduleUuid, p.module_uuid_path as moduleUuidPath, p.main_branch_project_uuid as mainBranchProjectUuid, p.kee as kee, p.name as name, p.long_name as longName, p.description as description, p.tags as tagsString, p.qualifier as qualifier, p.scope as scope, p.language as language, p.root_uuid as rootUuid, p.path as path, p.enabled as enabled, p.copy_component_uuid as copyComponentUuid, p.private as isPrivate, p.created_at as createdAt FROM projects p where p.uuid=? | params=AXWTSdq6zIDHJBORNEhX
2020.11.04 14:02:44 TRACE ce[AXWTkSH0zIDHJBORNEh7][sql] time=1ms | sql=select uuid, name, url, organization_uuid as organizationUuid, project_uuid as projectUuid, secret, created_at as createdAt, updated_at as updatedAt from webhooks where project_uuid = ? order by name asc | params=AXWTSdq6zIDHJBORNEhX
2020.11.04 14:02:44 TRACE ce[AXWTkSH0zIDHJBORNEh7][sql] time=0ms | sql=select uuid, name, url, organization_uuid as organizationUuid, project_uuid as projectUuid, secret, created_at as createdAt, updated_at as updatedAt from webhooks where organization_uuid = ? order by name asc | params=AW0W_wiGoQQ_ewQJ_Rv7
2020.11.04 14:02:44 TRACE ce[AXWTkSH0zIDHJBORNEh7][sql] time=0ms | sql=select p.prop_key as "key", p.is_empty as empty, p.text_value as textValue, p.clob_value as clobValue, p.resource_id as resourceId, p.user_id as userId from properties p where p.prop_key=? and p.resource_id is null and p.user_id is null | params=sonar.core.serverBaseURL
2020.11.04 14:02:44 DEBUG ce[AXWTkSH0zIDHJBORNEh7][o.s.s.w.WebHooksImpl] Sent webhook 'jenkins.svc.cluster.local' | url=http://jenkins.svc.cluster.local/jenkins/sonarqube-webhook/ | time=7ms | status=200
2020.11.04 14:02:44 TRACE ce[AXWTkSH0zIDHJBORNEh7][sql] time=1ms | sql=insert into webhook_deliveries ( uuid, webhook_uuid, component_uuid, ce_task_uuid, analysis_uuid, name, url, success, http_status, duration_ms, payload, error_stacktrace, created_at ) values ( ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ? ) | params=AXWTkSX4ohyalsuaF2fo, AW48eDTxKPWaCSguIKKa, AXWTSdq6zIDHJBORNEhX, AXWTkSH0zIDHJBORNEh7, AXWTkSSxohyalsuaF2ek, pe-datafabric-jenkins.pe-datafabric.svc.cluster.local, http://jenkins/jenkins/sonarqube-webhook/, true, 200, 7, {"serverUrl":"https://sonarqube/sonarqube","taskId":"AXWTkSH0zIDHJBORNEh7","status":"SUCCESS","analysedAt":"2020-11-04T14:02:39+0000","revision":"712c49228cda1ca6aceded78051d5deb2fa8d98f","changedAt":"2020-11-04T14:02:39+0000","project":{"key":"dprep-plugin-sample","name":"dprep-plugin-sample","url":"https://sonarqube/sonarqube/dashboard?id=dprep-plugin-sample"},"branch":{"name":"2","type":"PULL_REQUEST","isMain":false,"url":"htt..., 12, 1604498564593
2020.11.04 14:02:44 TRACE ce[AXWTkSH0zIDHJBORNEh7][sql] time=1ms | sql=delete from webhook_deliveries where component_uuid = ? and created_at < ? | params=AXWTSdq6zIDHJBORNEhX, 1601906564603
2020.11.04 14:02:44 DEBUG ce[AXWTkSH0zIDHJBORNEh7][c.g.m.s.p.c.p.PullRequestPostAnalysisTask] found 3 pull request decorators
2020.11.04 14:02:44 INFO  ce[AXWTkSH0zIDHJBORNEh7][c.g.m.s.p.c.p.PullRequestPostAnalysisTask] using pull request decorator Github
2020.11.04 14:02:44 TRACE ce[AXWTkSH0zIDHJBORNEh7][sql] time=1ms | sql=select p.prop_key as "key", p.is_empty as empty, p.text_value as textValue, p.clob_value as clobValue, p.resource_id as resourceId, p.user_id as userId from properties p where p.prop_key=? and p.resource_id is null and p.user_id is null | params=sonar.pullrequest.github.endpoint
2020.11.04 14:02:44 TRACE ce[AXWTkSH0zIDHJBORNEh7][sql] time=1ms | sql=select p.prop_key as "key", p.is_empty as empty, p.text_value as textValue, p.clob_value as clobValue, p.resource_id as resourceId, p.user_id as userId from properties p where p.prop_key=? and p.resource_id is null and p.user_id is null | params=sonar.alm.github.app.privateKey.secured
2020.11.04 14:02:44 TRACE ce[AXWTkSH0zIDHJBORNEh7][sql] time=0ms | sql=select p.prop_key as "key", p.is_empty as empty, p.text_value as textValue, p.clob_value as clobValue, p.resource_id as resourceId, p.user_id as userId from properties p where p.prop_key=? and p.resource_id is null and p.user_id is null | params=sonar.alm.github.app.id
2020.11.04 14:02:44 TRACE ce[AXWTkSH0zIDHJBORNEh7][sql] time=0ms | sql=select p.prop_key as "key", p.is_empty as empty, p.text_value as textValue, p.clob_value as clobValue, p.resource_id as resourceId, p.user_id as userId from properties p where p.prop_key=? and p.resource_id is null and p.user_id is null | params=sonar.alm.github.app.name
2020.11.04 14:02:44 TRACE ce[AXWTkSH0zIDHJBORNEh7][s.n.w.p.h.HttpURLConnection] ProxySelector Request for https://api.github.com/app/installations
...
...
2020.11.04 14:05:38 INFO  ce[AXWTkSH0zIDHJBORNEh7][o.s.c.t.CeWorkerImpl] Executed task | project=dprep-plugin-sample | type=REPORT | pullRequest=2 | id=AXWTkSH0zIDHJBORNEh7 | submitter=svc_gpsrm_jenkins | status=SUCCESS | time=174261ms

P.S.: use the #bug:fault sub-category if you’re hitting a specific crash/error , or the #bug:fp sub-category for rules-related behaviour

Hi,

Welcome to the community!

Actually, that’s just not how it works. Webhook calls are triggered server-side at the end of analysis report processing. A webhook cannot be called before Jenkins-side analysis is complete.

Probably you’re receiving the webhook from a different, earlier analysis and somehow the signals are crossing.

You’ve provided a lot of information in your post :clap:. It would be helpful if you could also provide your Jenkins job log.

 
Ann

Hi G Ann Campbell,

Thanks for the replay.

this is the time that sonarcube end to execute the scan sended by jenkins
“executedAt”: “2020-11-04T14:34:12+0000”
This is the time that jenkins get the POST
Nov 04, 2020 2:31:18 PM

you can validate that the task id is the same AXWTq0nKzIDHJBORNEiF

for other AXWTkSH0zIDHJBORNEh7 scan that I run with trace log levels you can see that the POST has been sent before the DB update to SUCCESS

...
2020.11.04 14:02:44 DEBUG ce[AXWTkSH0zIDHJBORNEh7][o.s.s.w.WebHooksImpl] Sent webhook 'jenkins.svc.cluster.local' | url=http://jenkins.svc.cluster.local/jenkins/sonarqube-webhook/ | time=7ms | status=200
...
2020.11.04 14:05:38 INFO  ce[AXWTkSH0zIDHJBORNEh7][o.s.c.t.CeWorkerImpl] Executed task | project=dprep-plugin-sample | type=REPORT | pullRequest=2 | id=AXWTkSH0zIDHJBORNEh7 | submitter=svc_gpsrm_jenkins | status=SUCCESS | time=174261ms
...

Jenkins build log

[INFO] SCM writing changed lines (done) | time=4ms
[INFO] Analysis report generated in 74ms, dir size=45 KB
[INFO] Analysis report compressed in 9ms, zip size=8 KB
[INFO] Analysis report uploaded in 99ms
[INFO] ANALYSIS SUCCESSFUL, you can browse https://***sonarqube/dashboard?id=dprep-plugin-sample&pullRequest=2
[INFO] Note that you will be able to access the updated dashboard once the server has processed the submitted analysis report
[INFO] More about the report processing at https://****-sonarqube/api/ce/task?id=AXWTq0nKzIDHJBORNEiF
[INFO] Analysis total time: 5.821 s
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  13.072 s
[INFO] Finished at: 2020-11-04T14:31:17Z
[INFO] ------------------------------------------------------------------------
[Pipeline] }
Deleting 1 temporary files
[Pipeline] // configFileProvider
[Pipeline] }
[Pipeline] // dir
[Pipeline] }
[Pipeline] // retry
[Pipeline] }
[Pipeline] // withCredentials
[Pipeline] }
[Pipeline] // script
[Pipeline] }
[Pipeline] // withSonarQubeEnv
[Pipeline] timeout
Timeout set to expire in 5 min 0 sec
[Pipeline] {
[Pipeline] waitForQualityGate
Checking status of SonarQube task 'AXWTq0nKzIDHJBORNEiF' on server 'sonarQube'
SonarQube task 'AXWTq0nKzIDHJBORNEiF' status is 'IN_PROGRESS'
Cancelling nested steps due to timeout
[Pipeline] }

Jenkins logs

Nov 04, 2020 2:31:18 PM INFO org.sonarsource.scanner.jenkins.pipeline.SonarQubeWebHook doIndex
Received POST from 127.0.0.1
Nov 04, 2020 2:31:18 PM FINE org.sonarsource.scanner.jenkins.pipeline.SonarQubeWebHook
Full details of the POST was {"serverUrl":"https://****-sonarqube","taskId":"AXWTq0nKzIDHJBORNEiF","status":"SUCCESS","analysedAt":"2020-11-04T14:31:13+0000","revision":"712c49228cda1ca6aceded78051d5deb2fa8d98f","changedAt":"2020-11-04T14:31:13+0000","project":{"key":"dprep-plugin-sample","name":"dprep-plugin-sample","url":"https://****/dashboard?id=dprep-plugin-sample"},"branch":{"name":"2","type":"PULL_REQUEST","isMain":false,"url":"https:/***/dashboard?id=dprep-plugin-sample&pullRequest=2"},"qualityGate":{"name":"QA Sonar way","status":"OK","conditions":[{"metric":"new_reliability_rating","operator":"GREATER_THAN","value":"1","status":"OK","errorThreshold":"1"},{"metric":"new_security_rating","operator":"GREATER_THAN","value":"1","status":"OK","errorThreshold":"1"},{"metric":"new_maintainability_rating","operator":"GREATER_THAN","value":"1","status":"OK","errorThreshold":"1"},{"metric":"new_duplicated_lines_density","operator":"GREATER_THAN","status":"NO_VALUE","errorThreshold":"3"}]},"properties":{}}

Hi,

Thanks for the Jenkins logs.

I understand now that you’re reporting(?) complaining(?) that the webhooks are triggered before the end of the background task computation. That is also normal.

Is this actually causing some sort of problem for you?

 
Ann

Hi G Ann Campbell,

the issue is with the jenkins step

waitForQualityGate

that get the webhook before the scans is ended. and when get the scan information
https://****-sonarqube/api/ce/task?id={ID}

the status is running instead of success

and the step waitForQualityGate stay blocked forever …

this step only check that status a single time ( at webhook reception on jenkins master )
[Pipeline] waitForQualityGate
Checking status of SonarQube task ‘AXWTq0nKzIDHJBORNEiF’ on server ‘sonarQube’
SonarQube task ‘AXWTq0nKzIDHJBORNEiF’ status is ‘IN_PROGRESS’

Hi,

Is it possible that you have multiple runs interfering with each other? None of this is making sense to me otherwise.

 
Ann

Hey there.

The issue is fixed with v2.12 of the Jenkins plugin (SONARJNKNS-320).

Time to upgrade :slight_smile:

thanks @Colin_SonarSource :grinning: