Pull Request decoration fails against Azure DevOps

aclaus · January 12, 2022, 11:59pm

Sonarqube version 8.9.6

The problem:
“Pull Request decoration failed: Unable to contact Azure DevOps server, got an unexpected response”

Pull request decoration seemed to be working fine last week, however today we started noticing sonarqube would fail to post back to our pull requests with a status update nor decoration.

I do not believe we have made to our Azure DevOps configuration, sonarqube version/configuration, nor the projects. We have checked to make sure the PAT and azure devops URL is correct.

Here is the relevant logs from the ComputeEngine on debug:

2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][c.s.G.D.D.H] Azure DevOps's instance URL from the scanner 'https://REDACTED.visualstudio.com/' is overridden by the settings 'https://REDACTED.visualstudio.com/'
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.s.a.c.a.AzureDevOpsHttpClient] get repo : [https://REDACTED.visualstudio.com/Sandbox/_apis/git/repositories/AClaus-SampleSwift?api-version=3.0]
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.http2.Http2] >> CONNECTION 505249202a20485454502f322e300d0a0d0a534d0d0a0d0a
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.http2.Http2] >> 0x00000000     6 SETTINGS      
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.http2.Http2] >> 0x00000000     4 WINDOW_UPDATE 
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.c.TaskRunner] Q10637 scheduled after   0 µs: OkHttp REDACTED.visualstudio.com
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.c.TaskRunner] Q10003 scheduled after   0 µs: OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.http2.Http2] >> 0x00000003   155 HEADERS       END_STREAM|END_HEADERS
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10637 starting              : OkHttp REDACTED.visualstudio.com
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10003 starting              : OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10003 run again after 300 s : OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000000    18 SETTINGS      
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10003 finished run in   1 ms: OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10634 scheduled after   0 µs: OkHttp REDACTED.visualstudio.com applyAndAckSettings
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000000     4 WINDOW_UPDATE 
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10634 starting              : OkHttp REDACTED.visualstudio.com applyAndAckSettings
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10636 scheduled after   0 µs: OkHttp REDACTED.visualstudio.com onSettings
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000000     0 SETTINGS      ACK
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] >> 0x00000000     0 SETTINGS      ACK
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10636 starting              : OkHttp REDACTED.visualstudio.com onSettings
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10634 finished run in   1 ms: OkHttp REDACTED.visualstudio.com applyAndAckSettings
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10636 finished run in   1 ms: OkHttp REDACTED.visualstudio.com onSettings
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000003  1677 HEADERS       END_HEADERS
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000003   662 DATA          
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000003     0 DATA          END_STREAM
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.c.TaskRunner] Q10003 scheduled after   0 µs: OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10003 starting              : OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10003 run again after 300 s : OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10003 finished run in 725 µs: OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.http2.Http2] >> CONNECTION 505249202a20485454502f322e300d0a0d0a534d0d0a0d0a
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.http2.Http2] >> 0x00000000     6 SETTINGS      
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.http2.Http2] >> 0x00000000     4 WINDOW_UPDATE 
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.c.TaskRunner] Q10641 scheduled after   0 µs: OkHttp spsprodcus1.vssps.visualstudio.com
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10641 starting              : OkHttp spsprodcus1.vssps.visualstudio.com
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.c.TaskRunner] Q10003 scheduled after   0 µs: OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10003 starting              : OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10003 run again after 300 s : OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000000    18 SETTINGS      
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.http2.Http2] >> 0x00000003   309 HEADERS       END_STREAM|END_HEADERS
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10003 finished run in   2 ms: OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10638 scheduled after   0 µs: OkHttp spsprodcus1.vssps.visualstudio.com applyAndAckSettings
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000000     4 WINDOW_UPDATE 
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10638 starting              : OkHttp spsprodcus1.vssps.visualstudio.com applyAndAckSettings
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10640 scheduled after   0 µs: OkHttp spsprodcus1.vssps.visualstudio.com onSettings
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] >> 0x00000000     0 SETTINGS      ACK
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10640 starting              : OkHttp spsprodcus1.vssps.visualstudio.com onSettings
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10640 finished run in 117 µs: OkHttp spsprodcus1.vssps.visualstudio.com onSettings
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10638 finished run in   1 ms: OkHttp spsprodcus1.vssps.visualstudio.com applyAndAckSettings
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000000     0 SETTINGS      ACK
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000003  1828 HEADERS       END_HEADERS
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000003  3440 DATA          
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000003  8192 DATA          
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000003  2239 DATA          
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000003  1806 DATA          
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.http2.Http2] >> 0x00000003     4 RST_STREAM    
2022.01.12 23:11:10 DEBUG ce[AX5QjzIqiGMo2UkrwAuh][o.i.c.TaskRunner] Q10003 scheduled after   0 µs: OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10003 starting              : OkHttp ConnectionPool
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10003 run again after 300 s : OkHttp ConnectionPool
2022.01.12 23:11:10 WARN  ce[AX5QjzIqiGMo2UkrwAuh][c.s.G.D.D.C] Pull Request decoration failed
java.lang.IllegalArgumentException: Unable to contact Azure DevOps server, got an unexpected response
	at org.sonar.alm.client.azure.AzureDevOpsHttpClient.doCall(AzureDevOpsHttpClient.java:117)
	at org.sonar.alm.client.azure.AzureDevOpsHttpClient.doGet(AzureDevOpsHttpClient.java:109)
	at org.sonar.alm.client.azure.AzureDevOpsHttpClient.getRepo(AzureDevOpsHttpClient.java:91)
	at com.sonarsource.G.D.D.E.A(Unknown Source)
	at com.sonarsource.G.D.D.C.A(Unknown Source)
	at com.sonarsource.G.D.D.C.A(Unknown Source)
	at java.base/java.util.Optional.ifPresent(Unknown Source)
	at com.sonarsource.G.D.D.C.A(Unknown Source)
	at com.sonarsource.G.D.c.A(Unknown Source)
	at java.base/java.util.Optional.ifPresent(Unknown Source)
	at com.sonarsource.G.D.c.B(Unknown Source)
	at com.sonarsource.G.D.c.A(Unknown Source)
	at org.sonar.ce.async.SynchronousAsyncExecution.addToQueue(SynchronousAsyncExecution.java:27)
	at com.sonarsource.G.D.c.A(Unknown Source)
	at java.base/java.util.Optional.ifPresent(Unknown Source)
	at com.sonarsource.G.D.c.finished(Unknown Source)
	at org.sonar.ce.task.projectanalysis.api.posttask.PostProjectAnalysisTasksExecutor.executeTask(PostProjectAnalysisTasksExecutor.java:118)
	at org.sonar.ce.task.projectanalysis.api.posttask.PostProjectAnalysisTasksExecutor.finished(PostProjectAnalysisTasksExecutor.java:109)
	at org.sonar.ce.task.step.ComputationStepExecutor.executeListener(ComputationStepExecutor.java:91)
	at org.sonar.ce.task.step.ComputationStepExecutor.execute(ComputationStepExecutor.java:63)
	at org.sonar.ce.task.projectanalysis.taskprocessor.ReportTaskProcessor.process(ReportTaskProcessor.java:81)
	at org.sonar.ce.taskprocessor.CeWorkerImpl$ExecuteTask.executeTask(CeWorkerImpl.java:212)
	at org.sonar.ce.taskprocessor.CeWorkerImpl$ExecuteTask.run(CeWorkerImpl.java:194)
	at org.sonar.ce.taskprocessor.CeWorkerImpl.findAndProcessTask(CeWorkerImpl.java:160)
	at org.sonar.ce.taskprocessor.CeWorkerImpl$TrackRunningState.get(CeWorkerImpl.java:135)
	at org.sonar.ce.taskprocessor.CeWorkerImpl.call(CeWorkerImpl.java:87)
	at org.sonar.ce.taskprocessor.CeWorkerImpl.call(CeWorkerImpl.java:53)
	at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:125)
	at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:69)
	at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:78)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
	at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.base/java.lang.Thread.run(Unknown Source)
Caused by: com.google.gson.JsonSyntaxException: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 3 column 1 path $
	at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:226)
	at com.google.gson.Gson.fromJson(Gson.java:932)
	at com.google.gson.Gson.fromJson(Gson.java:870)
	at org.sonar.alm.client.azure.AzureDevOpsHttpClient.lambda$getRepo$2(AzureDevOpsHttpClient.java:91)
	at org.sonar.alm.client.azure.AzureDevOpsHttpClient.doCall(AzureDevOpsHttpClient.java:115)
	... 35 common frames omitted
Caused by: java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at line 3 column 1 path $
	at com.google.gson.stream.JsonReader.beginObject(JsonReader.java:386)
	at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.read(ReflectiveTypeAdapterFactory.java:215)
	... 39 common frames omitted
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] << 0x00000003     0 DATA          END_STREAM
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10638 scheduled after   0 µs: OkHttp spsprodcus1.vssps.visualstudio.com[3] writeSynReset
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10638 starting              : OkHttp spsprodcus1.vssps.visualstudio.com[3] writeSynReset
2022.01.12 23:11:10 DEBUG ce[][o.i.http2.Http2] >> 0x00000003     4 RST_STREAM    
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10638 finished run in 220 µs: OkHttp spsprodcus1.vssps.visualstudio.com[3] writeSynReset
2022.01.12 23:11:10 DEBUG ce[][o.i.c.TaskRunner] Q10003 finished run in 189 µs: OkHttp ConnectionPool
2022.01.12 23:11:10 INFO  ce[AX5QjzIqiGMo2UkrwAuh][o.s.c.t.p.a.p.PostProjectAnalysisTasksExecutor] Pull Request decoration | status=SUCCESS | time=401ms

ganncamp · January 13, 2022, 3:21pm

Hi,

You haven’t changed the SonarQube end, and you haven’t changed the ADO end. Can you check with your network folks to make sure they haven’t changed what’s in the middle?

Ann

aclaus · January 13, 2022, 3:36pm

Hi Ann,

Is there anything specific I should be looking for?

Unfortunately the debug/trace output is not very helpful with giving me a starting point on what the HTTP request/response is, or even the endpoint being hit. Is there another way to see this information?

Thanks!
Andrew

aclaus · January 13, 2022, 3:41pm

Also, another note, it still does show the ALM integration configuration is valid.

ganncamp · January 13, 2022, 4:56pm

Hi,

The failure is in decorating the unredacted version of https://redacted.visualstudio.com/Sandbox/_apis/git/repositories/AClaus-SampleSwift?api-version=3.0, right? What happens when you call that URL directly? Does it work?

Ann

aclaus · January 13, 2022, 5:16pm

Yes, here is the response from that URL:

{"id":"2ea07271-496b-4e13-94bb-cd4de83218e9","name":"AClaus-SampleSwift","url":"https://REDACTED.visualstudio.com/6718806a-1caa-4870-944d-0d11842a1444/_apis/git/repositories/2ea07271-496b-4e13-94bb-cd4de83218e9","project":{"id":"6718806a-1caa-4870-944d-0d11842a1444","name":"Sandbox","description":"Tesseract projects only","url":"https://REDACTED.visualstudio.com/_apis/projects/6718806a-1caa-4870-944d-0d11842a1444","state":"wellFormed","revision":1181,"visibility":"private","lastUpdateTime":"2020-07-08T16:56:53.413Z"},"defaultBranch":"refs/heads/master","size":23002230,"remoteUrl":"https://REDACTED.visualstudio.com/Sandbox/_git/AClaus-SampleSwift","sshUrl":"REDACTED@vs-ssh.visualstudio.com:v3/REDACTED/Sandbox/AClaus-SampleSwift","webUrl":"https://REDACTED.visualstudio.com/Sandbox/_git/AClaus-SampleSwift","_links":{"self":{"href":"https://REDACTED.visualstudio.com/6718806a-1caa-4870-944d-0d11842a1444/_apis/git/repositories/2ea07271-496b-4e13-94bb-cd4de83218e9"},"project":{"href":"vstfs:///Classification/TeamProject/6718806a-1caa-4870-944d-0d11842a1444"},"web":{"href":"https://REDACTED.visualstudio.com/Sandbox/_git/AClaus-SampleSwift"},"ssh":{"href":"REDACTED@vs-ssh.visualstudio.com:v3/REDACTED/Sandbox/AClaus-SampleSwift"},"commits":{"href":"https://REDACTED.visualstudio.com/6718806a-1caa-4870-944d-0d11842a1444/_apis/git/repositories/2ea07271-496b-4e13-94bb-cd4de83218e9/commits"},"refs":{"href":"https://REDACTED.visualstudio.com/6718806a-1caa-4870-944d-0d11842a1444/_apis/git/repositories/2ea07271-496b-4e13-94bb-cd4de83218e9/refs"},"pullRequests":{"href":"https://REDACTED.visualstudio.com/6718806a-1caa-4870-944d-0d11842a1444/_apis/git/repositories/2ea07271-496b-4e13-94bb-cd4de83218e9/pullRequests"},"items":{"href":"https://REDACTED.visualstudio.com/6718806a-1caa-4870-944d-0d11842a1444/_apis/git/repositories/2ea07271-496b-4e13-94bb-cd4de83218e9/items"},"pushes":{"href":"https://REDACTED.visualstudio.com/6718806a-1caa-4870-944d-0d11842a1444/_apis/git/repositories/2ea07271-496b-4e13-94bb-cd4de83218e9/pushes"}},"isDisabled":false}

ganncamp · January 13, 2022, 5:50pm

Hi,

I’m out of my depth and have flagged this for more expert attention. In the meantime, since you get a seemingly valid response when you call the URL directly but clearly the SonarQube server gets something unexpected… Do you have the ability to run something like Wireshark on the SonarQube server to eavesdrop on that call and see what the response is? I have the sense that seeing the return value SonarQube gets from that call could be really helpful.

Ann

aclaus · February 7, 2022, 6:46pm

Hi @ganncamp!

This issue is still ongoing for us. I am not sure if we are able to run something like Wireshark to eavesdrop on the traffic because I believe we are running the docker container in Kubernetes. I am a little out of my depth in trying to debug further on my own.

Is there someone that can help us walkthrough debugging further on this?

Thanks!
Andrew

aclaus · February 7, 2022, 9:48pm

Actually, it looks like we just figured it out!

I am not sure if this setting was here before, but the solution was to give the Azure DevOps Personal Access Token the Code > Status permission in addition to Code > Read & Write. See:

The sonarqube documentation only mentions that it needs Code > Read & Write, perhaps that should get updated?
https://docs.sonarqube.org/8.9/analysis/azuredevops-integration/

Our PAT did not get changed, it was working fine without this additional permission up until the night of 1/11/2022, so Azure DevOps must have started to require it then.

ganncamp · February 8, 2022, 12:50pm

Hi Andrew,

Thanks for sharing your solution! I’ll pass it on to the team & see if we should update the docs.

Ann

Christophe_Havard · February 9, 2022, 8:49am

Hi @Andrew ,
Can you tell us which version of Azure DevOps Server you are using?

aclaus · April 12, 2022, 4:33pm

We are using Azure DevOps Services, sorry this was not clarified earlier.

(I see the error message above mentions “Azure DevOps server”, but that seems to be a generic message and it is not aware if it is “Server” or “Services”)

Christophe_Havard · April 25, 2022, 1:33pm

Hi @aclaus , it’s weird because we are not able to reproduce this behavior on our side. It seems like the Code:Read&Write is enough.
Is there any other setting you might have enable on your organization that would make Azure DevOps to require a Status permission as well?

Thanks!
Christophe

aclaus · April 25, 2022, 4:28pm

We could not find anything that changed on our end, but if you have any ideas on settings you think might be the cause, I would be happy to share what those settings look like on our end.

Christophe_Havard · April 26, 2022, 7:59am

well, to be honest, I have no idea
we will keep investigate on our side and keep you posted if we ever find anything or if someone else have the same issue
Thanks,
Christophe