When running the Docker solution aggregator-host states "Connecting to Azure DevOps using PAT..." and executes no rule

[theTestTube]

Thanks in advance! 👦

Steps to reproduce

Configuring runtime and a new test1 rule following Docker setup instructions,

$"Hello { self.WorkItemType } #{ self.Id } - { self.Title }!"

Running docker image,

docker run --rm -it -p 5320:5320 -e Aggregator_VstsToken=$Aggregator_Token -e Aggregator_SharedSecret=$Aggregator_SharedSecret -e ASPNETCORE_Kestrel__Certificates__Default__Password="$Certificate_Password" -e Aggregator_AzureDevOpsCertificate=$Aggregator_AzureDevOpsCertificate -v $Source/aggregator-cli/docker/rules:/rules  -v $Source/aggregator-cli/docker/secrets:/secrets   tfsaggregator/aggregator3:latest

Testing Ok status,

curl -X GET https://$HostName:5320/config/status

Log in to ADO,

aggregator-cli logon.ado --url https://$DevOpsHostName/$DevOpsCollection --mode PAT --token $MyToken

Mapping a local rule,

aggregator-cli map.local.rule --targetUrl https://$HostName:5320 --rule test1 --project TestRoadmap --event workitem.updated 

Updating a work item and correctly receiving REST request on aggregator-host Docker process.

I've also correctly checked connectivity from the Docker machine shell to Azure DevOps with wget --no-check-certificate https://...

Expected behavior

Output from test1 execution was expected.

Actual behavior

Before actually running the test1 function last successfull message is Connecting to Azure DevOps using PAT... followed by Waiting 00:00:30 before retrying (attemp #1/3)... and an A task was canceled error message.

Diagnostic logs

These are the traces upon work item update, including the fail message,

dbug: Aggregator[0]
      Loading API Keys from /secrets/apikeys.json
info: Aggregator[0]
      Loaded 2 API Keys
warn: Microsoft.AspNetCore.DataProtection.Repositories.FileSystemXmlRepository[60]
      Storing keys in a directory '/root/.aspnet/DataProtection-Keys' that may not be persisted outside of the container.
info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[0]
      User profile is available. Using '/root/.aspnet/DataProtection-Keys' as key repository; keys will not be encrypted 
info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[58]
      Creating key {c40646d4-218a-4e4f-8f86-4b0dd040336e} with creation date 2021-10-14 11:12:51Z, activation date 2021-1
warn: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[35]
      No XML encryptor configured. Key {c40646d4-218a-4e4f-8f86-4b0dd040336e} may be persisted to storage in unencrypted 
info: Microsoft.AspNetCore.DataProtection.Repositories.FileSystemXmlRepository[39]
      Writing data to file '/root/.aspnet/DataProtection-Keys/key-c40646d4-218a-4e4f-8f86-4b0dd040336e.xml'.
info: Microsoft.Hosting.Lifetime[0]
      Now listening on: https://[::]:5320
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Production
info: Microsoft.Hosting.Lifetime[0]
      Content root path: /app
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 POST https://devops-aggregator.example.net:5320/workitem/test1 application/json; charset
dbug: aggregator_host.ApiKeyAuthenticationHandler[8]
      AuthenticationScheme: ApiKeyAuthenticationScheme was successfully authenticated.
dbug: aggregator_host.ApiKeyAuthenticationHandler[8]
      AuthenticationScheme: ApiKeyAuthenticationScheme was successfully authenticated.
info: Microsoft.AspNetCore.Authorization.DefaultAuthorizationService[1]
      Authorization was successful.
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'aggregator_host.Controllers.WorkItemController.PostAsync (aggregator-host)'
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
      Route matched with {action = "Post", controller = "WorkItem"}. Executing controller action with signature System.ThAsync(Microsoft.VisualStudio.Services.ServiceHooks.WebApi.WebHookEvent, System.String, System.Threading.CancellationTokenggregator-host).
info: Aggregator[0]
      Aggregator v1.1.0 executing rule 'test1'
dbug: Aggregator[0]
      Searching 'test1' in /rules
dbug: Aggregator[0]
      Rule code found at /rules/test1.rule
dbug: Aggregator[0]
      Connecting to Azure DevOps using PAT...
info: Aggregator[0]

      Waiting 00:00:30 before retrying (attemp #1/3)...
fail: Aggregator[0]
      A task was canceled.
warn: Aggregator[0]
      Rule 'test1' failed: A task was canceled.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'System.String'.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
      Executed action aggregator_host.Controllers.WorkItemController.PostAsync (aggregator-host) in 29845.5847ms
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'aggregator_host.Controllers.WorkItemController.PostAsync (aggregator-host)'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 29991.1866ms 400 text/plain; charset=utf-8

These are the traces for a correct Azure DevOps project webhook test execution,

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 POST https://devops-aggregator.example.net:5320/workitem/test1 application/json; charset=utf-8 4050
dbug: aggregator_host.ApiKeyAuthenticationHandler[8]
      AuthenticationScheme: ApiKeyAuthenticationScheme was successfully authenticated.
dbug: aggregator_host.ApiKeyAuthenticationHandler[8]
      AuthenticationScheme: ApiKeyAuthenticationScheme was successfully authenticated.
info: Microsoft.AspNetCore.Authorization.DefaultAuthorizationService[1]
      Authorization was successful.
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[0]
      Executing endpoint 'aggregator_host.Controllers.WorkItemController.PostAsync (aggregator-host)'
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[3]
      Route matched with {action = "Post", controller = "WorkItem"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] PostAsync(Microsoft.VisualStudio.Services.ServiceHooks.WebApi.WebHookEvent, System.String, System.Threading.CancellationToken) on controller aggregator_host.Controllers.WorkItemController (aggregator-host).
info: Aggregator[0]
      Aggregator v1.1.0 executing rule 'test1'
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type '<>f__AnonymousType1`1[[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]'.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
      Executed action aggregator_host.Controllers.WorkItemController.PostAsync (aggregator-host) in 20.1134ms
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'aggregator_host.Controllers.WorkItemController.PostAsync (aggregator-host)'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 21.4581ms 200 application/json; charset=utf-8

Environment

Running Azure DevOps Server 2020.1 on-premise.

Running the tfsaggregator/aggregator3:latest, I wouldn't mind running the aggregator-host process for v1.1.0 release in my IIS or a custom-built docker image with trace logs if I had known how to do it.

[giuliov]

My first reaction, reading the log, is that Aggregator is not able to connect to Azure DevOps. You mentioned that checked the connection using wget --no-check-certificate https://... which rule out DNS issues, so I suspect an SSL issue. Are you tried using Aggregator_AzureDevOpsCertificate to add AzDO certificate to the trusted ones?

[theTestTube]

Dear @giuliov, thanks for your fast response.

Yes, an Aggregator_AzureDevOpsCertificate has been specified and I've checked twice the /secrets/tfs.cer used for trust is present and readable,

/app # ls -lta $Aggregator_AzureDevOpsCertificate
-rwxrwxrwx    1 root     root          1889 Oct  8 11:23 /secrets/tfs.cer

Please notice this is the Azure DevOps 2020 server certificate including the root and intermediate CAs,

May be another clue could give you some more info, testing the webhook from "Project Settings; Service hooks" works properly,

info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type '<>f__AnonymousType1`1[[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]'.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
      Executed action aggregator_host.Controllers.WorkItemController.PostAsync (aggregator-host) in 19.4591ms
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'aggregator_host.Controllers.WorkItemController.PostAsync (aggregator-host)'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 22.0227ms 200 application/json; charset=utf-8

While invoking through WIT update fails,

dbug: Aggregator[0]
      Searching 'test1' in /rules
dbug: Aggregator[0]
      Rule code found at /rules/test1.rule
dbug: Aggregator[0]
      Connecting to Azure DevOps using PAT...
info: Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor[1]
      Executing ObjectResult, writing value of type 'System.String'.
info: Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker[2]
      Executed action aggregator_host.Controllers.WorkItemController.PostAsync (aggregator-host) in 29970.8469ms
info: Microsoft.AspNetCore.Routing.EndpointMiddleware[1]
      Executed endpoint 'aggregator_host.Controllers.WorkItemController.PostAsync (aggregator-host)'
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 29973.967ms 400 text/plain; charset=utf-8

[giuliov]

Sorry for the delay, I am on the road with just one laptop.

Recapping:

1. testing the webhook, passes implies that connection from AzDO to Agg is fine: the bogus message is handled in Agg before loading the rule interpreter;
2. invoking a simple "hello world" rule, fails the rule interpreter is loaded and before interpreting the rule, it calls back AzDO to get some context information;

That connection is controlled by a Polly policy in RuleExecutor.ConnectToAzureDevOpsAsync method. It attempts a connection and retries when AzDO replies with an HTTP status 429 (Too Many Requests). We see the message Waiting 00:00:30 before retrying infact. I do not understand the A task was canceled message happening so quick, you should see additional retry messages.

[theTestTube]

Dear Giulio,

Your recap is right. I've also checked that no callback to AzDO is taking place at the time it states Connecting to Azure DevOps using PAT....

To check this I've,

• Checked my HostName and OrganizationName bash vars match those received in the Agg HTTP rule1 execution webhook and correct UserName, and Aggregator_Token are also specified
• Made a dumb request from the Docker machine to identify the AzDO access log point in time, wget -o stdout --no-check-certificate "https://$UserName:$Aggregator_Token@$HostName/$OrganizationName/_apis/projects?api-version=2.0&nonsense1"
• Forced test1 execution by making a WIT change
• Waited for Agg stating Connecting to Azure DevOps using PAT..., also Waiting 00:00:30 before retrying (attemp #1/3)... and even A task was canceled
• Made another dumb request from the Docker machine to identify the access log point in time, wget ...?api-version=2.0&nonsense2"

I inspected Azure DevOps 2020 Server access logs and found no request from my Docker machine between the nonsense1 and nonsense2 HTTPS requests.

I wonder where the hell is Agg making the HTTPS request to. How could I trace it? Is there any option to log debug info including the target URL for the Connecting to Azure DevOps using PAT... request?

Apart, is there any guide to make Agg work outside Docker (as a .Net WebAPI in IIS, for example), in order to debug the project with Visual Studio 2019 and have all this information on our own?

Many thanks.-

[giuliov]

Building on your machine is trivial. There is a single solution for all flavours. In this scenario I launch aggregator-host.csproj project. Debugging is a bit complex. The host project must use TLS, with a certificate trusted by AzDO, reachable with a proper DNS name, port must be open on local firewall. You must define the API key(s), the Aggregator_SharedSecret environment variable to enable the CLI. The rule files can be in the bin directory or in the directory defined by Aggregator_RulesPath.

HTH

[giuliov]

I haven't heard you in a while. Have you solved the issue? You mentioned that DNS resolution from the machine hosting the container, but is it working from within the container?