Pull Request decoration fails against Azure DevOps

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

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

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

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

image

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

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}

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