ServiceInvocationSample - error when using CreateInvokeHttpClient

larserikfinholt commented 2 years ago

Fresh install of Dapr 1.5. Opens the all.sln in VS2022 and set ServiceInvocationSample as default.

When hitting the /sidecar an exception happens:

Below are the logs until I hit the endpoint

[13:29:15 INF] Dapr Process Status Change: Stopped -> Initializing
[13:29:15 INF] AppId not specified, assigning default value: serviceinvocationsample
[13:29:15 INF] Dapr expected process name set to daprd
[13:29:15 INF] Now listening on: http://localhost:5000
[13:29:15 INF] Application started. Press Ctrl+C to shut down.
[13:29:15 INF] Hosting environment: Development
[13:29:15 INF] Content root path: C:\Projects\dapr-sidekick-dotnet\samples\AspNetCore\ServiceInvocationSample\ServiceInvocationSample
[13:29:15 INF] Dapr initial directory: C:\Users\lars.erik.finholt\.dapr
[13:29:15 INF] Dapr runtime directory: C:\Users\lars.erik.finholt\.dapr
[13:29:15 INF] Dapr process binary: C:\Users\lars.erik.finholt\.dapr\bin\daprd.exe
[13:29:15 INF] Dapr Process Status Change: Initializing -> Starting
[13:29:15 INF] Environment variable DAPR_GRPC_PORT set to 50001
[13:29:15 INF] Environment variable DAPR_HTTP_PORT set to 3500
[13:29:15 INF] Starting Process C:\Users\lars.erik.finholt\.dapr\bin\daprd.exe with arguments '--app-id serviceinvocationsample --app-port 5000 --dapr-grpc-port 50001 --dapr-http-port 3500 --log-as-json --log-level debug --metrics-port 9090 --placement-host-address 127.0.0.1:6050 --config C:\Users\lars.erik.finholt\.dapr\config.yaml --components-path C:\Users\lars.erik.finholt\.dapr\components'
[13:29:15 INF] Process daprd PID:10756 started successfully
[13:29:19 INF] Request starting HTTP/1.1 GET http://localhost:5000/weatherforecast/status
[13:29:20 INF] 2021/11/19 13:29:19 maxprocs: Leaving GOMAXPROCS=4: CPU quota undefined
[13:29:20 INF] Executing endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetStatus (ServiceInvocationSample)'
[13:29:20 INF] starting Dapr Runtime -- version 1.5.0 -- commit 83fe579f5dc93bef1ce3b464d3167a225a3aff3a
[13:29:20 INF] log level set to: debug
[13:29:20 INF] Route matched with {action = "GetStatus", controller = "WeatherForecast"}. Executing controller action with signature Microsoft.AspNetCore.Mvc.ActionResult GetStatus() on controller ServiceInvocationSample.Controllers.WeatherForecastController (ServiceInvocationSample).
[13:29:20 INF] metrics server started on :9090/
[13:29:20 INF] standalone mode configured
[13:29:20 INF] app id: serviceinvocationsample
[13:29:20 INF] mTLS is disabled. Skipping certificate request and tls validation
[13:29:20 INF] Executing ObjectResult, writing value of type '<>f__AnonymousType0`2[[Man.Dapr.Sidekick.Process.DaprProcessInfo, Man.Dapr.Sidekick, Version=1.0.0.0, Culture=neutral, PublicKeyToken=740d643db1ccf811],[Man.Dapr.Sidekick.DaprSidecarOptions, Man.Dapr.Sidekick, Version=1.0.0.0, Culture=neutral, PublicKeyToken=740d643db1ccf811]]'.
[13:29:21 INF] Executed action ServiceInvocationSample.Controllers.WeatherForecastController.GetStatus (ServiceInvocationSample) in 120.6466ms
[13:29:21 INF] Executed endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetStatus (ServiceInvocationSample)'
[13:29:21 INF] Request finished in 1098.4343ms 200 application/json; charset=utf-8
[13:29:21 INF] local service entry announced: serviceinvocationsample -> 10.99.16.103:51494
[13:29:21 INF] Initialized name resolution to mdns
[13:29:21 INF] loading components
[13:29:21 INF] component loaded. name: pubsub, type: pubsub.redis/v1
[13:29:21 INF] Request starting HTTP/1.1 GET http://127.0.0.1:5000/dapr/config application/json
[13:29:21 INF] waiting for all outstanding components to be processed
[13:29:21 INF] Request finished in 6.6887ms 404
[13:29:21 INF] component loaded. name: statestore, type: state.redis/v1
[13:29:21 INF] all outstanding components processed
[13:29:21 INF] enabled gRPC tracing middleware
[13:29:21 INF] Request starting HTTP/1.1 GET http://127.0.0.1:5000/dapr/subscribe application/json
[13:29:21 INF] enabled gRPC metrics middleware
[13:29:21 INF] Request finished in 3.5232ms 404
[13:29:21 INF] API gRPC server is running on port 50001
[13:29:21 INF] enabled metrics http middleware
[13:29:21 INF] enabled tracing http middleware
[13:29:21 INF] http server is running on port 3500
[13:29:21 INF] The request body size parameter is: 4
[13:29:22 INF] enabled gRPC tracing middleware
[13:29:22 INF] enabled gRPC metrics middleware
[13:29:22 INF] internal gRPC server is running on port 51494
[13:29:22 INF] application protocol: http. waiting on port 5000.  This will block until the app is listening on that port.
[13:29:22 INF] application discovered on port 5000
[13:29:22 INF] application configuration loaded
[13:29:22 INF] actor runtime started. actor idle timeout: 1h0m0s. actor scan interval: 30s
[13:29:22 INF] placement tables updated, version: 0
[13:29:22 INF] dapr initialized. Status: Running. Init Elapsed 1221.5228ms
[13:29:22 INF] Dapr Process Status Change: Starting -> Started
[13:29:22 INF] Caching successful startup options for future restart attempts
[13:29:26 INF] Request starting HTTP/1.1 GET http://localhost:5000/weatherforecast/sidecar
[13:29:26 INF] Executing endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample)'
[13:29:26 INF] Route matched with {action = "GetViaSidecar", controller = "WeatherForecast"}. Executing controller action with signature System.Threading.Tasks.Task`1[System.Collections.Generic.IEnumerable`1[ServiceInvocationSample.WeatherForecast]] GetViaSidecar() on controller ServiceInvocationSample.Controllers.WeatherForecastController (ServiceInvocationSample).
[13:29:30 INF] Executed action ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample) in 3999.3558ms
[13:29:30 INF] Executed endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample)'
[13:29:30 ERR] An unhandled exception has occurred while executing the request.
System.Net.Http.HttpRequestException: Response status code does not indicate success: 500 (Internal Server Error).
   at System.Net.Http.HttpResponseMessage.EnsureSuccessStatusCode()
   at System.Net.Http.HttpClient.GetStringAsyncCore(Task`1 getTask)
   at ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar() in C:\Projects\dapr-sidekick-dotnet\samples\AspNetCore\ServiceInvocationSample\ServiceInvocationSample\Controllers\WeatherForecastController.cs:line 70
   at lambda_method(Closure , Object )
   at Microsoft.Extensions.Internal.ObjectMethodExecutorAwaitable.Awaiter.GetResult()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.AwaitableObjectResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)
[13:29:30 INF] Request finished in 4312.0357ms 500 text/html; charset=utf-8
[13:29:30 INF] Request starting HTTP/1.1 GET http://localhost:5000/_framework/aspnetcore-browser-refresh.js
[13:29:30 INF] Request finished in 72.8869ms 200 application/javascript; charset=utf-8
[13:31:46 INF] Request starting HTTP/1.1 GET http://localhost:5000/weatherforecast/sidecar
[13:31:46 INF] Executing endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample)'
[13:31:46 INF] Route matched with {action = "GetViaSidecar", controller = "WeatherForecast"}. Executing controller action with signature System.Threading.Tasks.Task`1[System.Collections.Generic.IEnumerable`1[ServiceInvocationSample.WeatherForecast]] GetViaSidecar() on controller ServiceInvocationSample.Controllers.WeatherForecastController (ServiceInvocationSample).

My first attempt with a ServiceA project calling a ServiceB project failed with the same error, that's why I tried the sample, and got the same result.

Any idea what I've done wrong?

badgeratu commented 2 years ago

Hmm, I've just done exactly the same thing as you - using VS2022 and Dapr 1.5.0 - and it worked first time:

[16:24:30 INF] Dapr Process Status Change: Stopped -> Initializing
[16:24:30 INF] AppId not specified, assigning default value: serviceinvocationsample
[16:24:30 INF] Dapr expected process name set to daprd
[16:24:30 INF] Now listening on: http://localhost:5000
[16:24:30 INF] Application started. Press Ctrl+C to shut down.
[16:24:30 INF] Hosting environment: Development
[16:24:30 INF] Content root path: C:\working\github\man-group\dapr-sidekick-dotnet\samples\AspNetCore\ServiceInvocationSample\ServiceInvocationSample
[16:24:30 INF] Dapr initial directory: C:\Users\scjones\.dapr
[16:24:30 INF] Dapr runtime directory: C:\Users\scjones\.dapr
[16:24:30 INF] Dapr process binary: C:\Users\scjones\.dapr\bin\daprd.exe
[16:24:30 INF] Dapr Process Status Change: Initializing -> Starting
[16:24:30 INF] Environment variable DAPR_GRPC_PORT set to 50001
[16:24:30 INF] Environment variable DAPR_HTTP_PORT set to 3500
[16:24:30 INF] Starting Process C:\Users\scjones\.dapr\bin\daprd.exe with arguments '--app-id serviceinvocationsample --app-port 5000 --dapr-grpc-port 50001 --dapr-http-port 3500 --log-as-json --log-level debug --metrics-port 9090 --placement-host-address 127.0.0.1:6050 --config C:\Users\scjones\.dapr\config.yaml --components-path C:\Users\scjones\.dapr\components'
[16:24:30 INF] Process daprd PID:52836 started successfully
[16:24:30 INF] 2021/11/19 16:24:30 maxprocs: Leaving GOMAXPROCS=12: CPU quota undefined
[16:24:30 INF] starting Dapr Runtime -- version 1.5.0 -- commit 83fe579f5dc93bef1ce3b464d3167a225a3aff3a
[16:24:31 INF] log level set to: debug
[16:24:31 INF] metrics server started on :9090/
[16:24:31 INF] standalone mode configured
[16:24:31 INF] app id: serviceinvocationsample
[16:24:31 INF] mTLS is disabled. Skipping certificate request and tls validation
[16:24:31 INF] local service entry announced: serviceinvocationsample -> 10.255.22.18:59166
[16:24:31 INF] Initialized name resolution to mdns
[16:24:31 INF] loading components
[16:24:31 INF] component loaded. name: pubsub, type: pubsub.redis/v1
[16:24:31 INF] waiting for all outstanding components to be processed
[16:24:31 INF] component loaded. name: statestore, type: state.redis/v1
[16:24:31 INF] all outstanding components processed
[16:24:31 INF] enabled gRPC tracing middleware
[16:24:31 INF] enabled gRPC metrics middleware
[16:24:31 INF] API gRPC server is running on port 50001
[16:24:31 INF] enabled metrics http middleware
[16:24:31 INF] Request starting HTTP/1.1 GET http://127.0.0.1:5000/dapr/config application/json
[16:24:31 INF] enabled tracing http middleware
[16:24:31 INF] http server is running on port 3500
[16:24:31 INF] The request body size parameter is: 4
[16:24:31 INF] enabled gRPC tracing middleware
[16:24:31 INF] enabled gRPC metrics middleware
[16:24:31 INF] internal gRPC server is running on port 59166
[16:24:31 INF] application protocol: http. waiting on port 5000.  This will block until the app is listening on that port.
[16:24:31 INF] application discovered on port 5000
[16:24:31 INF] Request finished in 83.1438ms 404
[16:24:31 INF] application configuration loaded
[16:24:31 INF] actor runtime started. actor idle timeout: 1h0m0s. actor scan interval: 30s
[16:24:31 INF] Request starting HTTP/1.1 GET http://127.0.0.1:5000/dapr/subscribe application/json
[16:24:31 INF] placement tables updated, version: 0
[16:24:31 INF] Request finished in 4.1962ms 404
[16:24:31 INF] dapr initialized. Status: Running. Init Elapsed 455.978ms
[16:24:31 INF] Dapr Process Status Change: Starting -> Started
[16:24:31 INF] Caching successful startup options for future restart attempts
[16:24:32 INF] Request starting HTTP/1.1 GET http://localhost:5000/weatherforecast/sidecar
[16:24:32 INF] Executing endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample)'
[16:24:32 INF] Route matched with {action = "GetViaSidecar", controller = "WeatherForecast"}. Executing controller action with signature System.Threading.Tasks.Task`1[System.Collections.Generic.IEnumerable`1[ServiceInvocationSample.WeatherForecast]] GetViaSidecar() on controller ServiceInvocationSample.Controllers.WeatherForecastController (ServiceInvocationSample).
[16:24:32 INF] Executing action method ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample) - Validation state: Valid
[16:24:32 INF] Request starting HTTP/1.1 GET http://127.0.0.1:5000/weatherforecast application/json
[16:24:32 INF] Executing endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.Get (ServiceInvocationSample)'
[16:24:32 INF] Route matched with {action = "Get", controller = "WeatherForecast"}. Executing controller action with signature System.Collections.Generic.IEnumerable`1[ServiceInvocationSample.WeatherForecast] Get() on controller ServiceInvocationSample.Controllers.WeatherForecastController (ServiceInvocationSample).
[16:24:32 INF] Executing action method ServiceInvocationSample.Controllers.WeatherForecastController.Get (ServiceInvocationSample) - Validation state: Valid
[16:24:32 INF] Executed action method ServiceInvocationSample.Controllers.WeatherForecastController.Get (ServiceInvocationSample), returned result Microsoft.AspNetCore.Mvc.ObjectResult in 1.6234ms.
[16:24:32 INF] Executing ObjectResult, writing value of type 'ServiceInvocationSample.WeatherForecast[]'.
[16:24:32 INF] Executed action ServiceInvocationSample.Controllers.WeatherForecastController.Get (ServiceInvocationSample) in 44.1392ms
[16:24:32 INF] Executed endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.Get (ServiceInvocationSample)'
[16:24:32 INF] Request finished in 86.362ms 200 application/json; charset=utf-8
[16:24:33 INF] Executed action method ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample), returned result Microsoft.AspNetCore.Mvc.ObjectResult in 678.5138ms.
[16:24:33 INF] Executing ObjectResult, writing value of type 'System.Collections.Generic.List`1[[ServiceInvocationSample.WeatherForecast, ServiceInvocationSample, Version=1.0.0.0, Culture=neutral, PublicKeyToken=740d643db1ccf811]]'.
[16:24:33 INF] Executed action ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample) in 782.6151ms
[16:24:33 INF] Executed endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample)'
[16:24:33 INF] Request finished in 897.9187ms 200 application/json; charset=utf-8

What happens if you attempt to invoke the method directly on the sidecar while the solution is running? The URL would be something like:

http://localhost:3500/v1.0/invoke/serviceinvocationsample/method/weatherforecast

For me the sidecar also returns a valid response, do you get the same?

badgeratu commented 2 years ago

Actually I don't think your call is ever reaching the Dapr sidecar, because it looks like ASP.NET Core is not validating the request properly. Note how in my sample above I have the following:

[16:24:32 INF] Request starting HTTP/1.1 GET http://localhost:5000/weatherforecast/sidecar
[16:24:32 INF] Executing endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample)'
[16:24:32 INF] Route matched with {action = "GetViaSidecar", controller = "WeatherForecast"}. Executing controller action with signature System.Threading.Tasks.Task`1[System.Collections.Generic.IEnumerable`1[ServiceInvocationSample.WeatherForecast]] GetViaSidecar() on controller ServiceInvocationSample.Controllers.WeatherForecastController (ServiceInvocationSample).
[16:24:32 INF] Executing action method ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample) - Validation state: Valid
[16:24:32 INF] Request starting HTTP/1.1 GET http://127.0.0.1:5000/weatherforecast application/json
[16:24:32 INF] Executing endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.Get (ServiceInvocationSample)'
[16:24:32 INF] Route matched with {action = "Get", controller = "WeatherForecast"}. Executing controller action with signature System.Collections.Generic.IEnumerable`1[ServiceInvocationSample.WeatherForecast] Get() on controller ServiceInvocationSample.Controllers.WeatherForecastController (ServiceInvocationSample).
[16:24:32 INF] Executing action method ServiceInvocationSample.Controllers.WeatherForecastController.Get (ServiceInvocationSample) - Validation state: Valid
[16:24:32 INF] Executed action method ServiceInvocationSample.Controllers.WeatherForecastController.Get (ServiceInvocationSample), returned result Microsoft.AspNetCore.Mvc.ObjectResult in 1.6234ms.

whereas in your example you have:

[13:29:26 INF] Request starting HTTP/1.1 GET http://localhost:5000/weatherforecast/sidecar
[13:29:26 INF] Executing endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample)'
[13:29:26 INF] Route matched with {action = "GetViaSidecar", controller = "WeatherForecast"}. Executing controller action with signature System.Threading.Tasks.Task`1[System.Collections.Generic.IEnumerable`1[ServiceInvocationSample.WeatherForecast]] GetViaSidecar() on controller ServiceInvocationSample.Controllers.WeatherForecastController (ServiceInvocationSample).
[13:29:30 INF] Executed action ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample) in 3999.3558ms
[13:29:30 INF] Executed endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample)'
[13:29:30 ERR] An unhandled exception has occurred while executing the request.

More specifically I have the following validation completed line:

[16:24:32 INF] Executing action method ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample) - Validation state: Valid

I'm not sure what in ASP.NET Core would cause this - maybe there's some .NET Core installation problem on your machine? Are you definitely running a completely clean clone of the sample solution with zero changes?

larserikfinholt commented 2 years ago

Thanks, for looking into this. Yes, it was a clean clone.

Today I installed into another machine, other user, cloned again (no changes) and this is what I get this time (403 forbidden) Endpoint works alone, exception at same location:

[10:30:04 INF] Dapr Process Status Change: Stopped -> Initializing
[10:30:04 INF] AppId not specified, assigning default value: serviceinvocationsample
[10:30:04 INF] Dapr expected process name set to daprd
[10:30:04 INF] Now listening on: http://localhost:5000
[10:30:04 INF] Application started. Press Ctrl+C to shut down.
[10:30:04 INF] Hosting environment: Development
[10:30:04 INF] Content root path: C:\temp\dapr-sidekick-dotnet\samples\AspNetCore\ServiceInvocationSample\ServiceInvocationSample
[10:30:04 INF] Dapr initial directory: C:\Users\k123433\.dapr
[10:30:04 INF] Dapr runtime directory: C:\Users\k123433\.dapr
[10:30:04 INF] Dapr process binary: C:\Users\k123433\.dapr\bin\daprd.exe
[10:30:04 INF] Dapr Process Status Change: Initializing -> Starting
[10:30:04 INF] Environment variable DAPR_GRPC_PORT set to 50001
[10:30:04 INF] Environment variable DAPR_HTTP_PORT set to 3500
[10:30:04 INF] Starting Process C:\Users\k123433\.dapr\bin\daprd.exe with arguments '--app-id serviceinvocationsample --app-port 5000 --dapr-grpc-port 50001 --dapr-http-port 3500 --log-as-json --log-level debug --metrics-port 9090 --placement-host-address 127.0.0.1:6050 --config C:\Users\k123433\.dapr\config.yaml --components-path C:\Users\k123433\.dapr\components'
[10:30:04 INF] Process daprd PID:11588 started successfully
[10:30:04 INF] 2021/11/22 10:30:04 maxprocs: Leaving GOMAXPROCS=4: CPU quota undefined
[10:30:04 INF] starting Dapr Runtime -- version 1.5.0 -- commit 83fe579f5dc93bef1ce3b464d3167a225a3aff3a
[10:30:04 INF] log level set to: debug
[10:30:04 INF] metrics server started on :9090/
[10:30:04 INF] standalone mode configured
[10:30:04 INF] app id: serviceinvocationsample
[10:30:04 INF] mTLS is disabled. Skipping certificate request and tls validation
[10:30:04 INF] local service entry announced: serviceinvocationsample -> 10.124.22.90:52496
[10:30:04 INF] Initialized name resolution to mdns
[10:30:04 INF] loading components
[10:30:04 INF] component loaded. name: pubsub, type: pubsub.redis/v1
[10:30:04 INF] waiting for all outstanding components to be processed
[10:30:04 INF] component loaded. name: statestore, type: state.redis/v1
[10:30:04 INF] all outstanding components processed
[10:30:04 INF] enabled gRPC tracing middleware
[10:30:04 INF] enabled gRPC metrics middleware
[10:30:04 INF] API gRPC server is running on port 50001
[10:30:04 INF] enabled metrics http middleware
[10:30:04 INF] Request starting HTTP/1.1 GET http://127.0.0.1:5000/dapr/config application/json
[10:30:04 INF] enabled tracing http middleware
[10:30:04 INF] http server is running on port 3500
[10:30:04 INF] The request body size parameter is: 4
[10:30:04 INF] enabled gRPC tracing middleware
[10:30:04 INF] enabled gRPC metrics middleware
[10:30:04 INF] internal gRPC server is running on port 52496
[10:30:04 INF] Request finished in 25.5687ms 404
[10:30:04 INF] application protocol: http. waiting on port 5000.  This will block until the app is listening on that port.
[10:30:04 INF] Request starting HTTP/1.1 GET http://127.0.0.1:5000/dapr/subscribe application/json
[10:30:04 INF] Request finished in 56.6605ms 404
[10:30:04 INF] application discovered on port 5000
[10:30:04 INF] application configuration loaded
[10:30:04 INF] actor runtime started. actor idle timeout: 1h0m0s. actor scan interval: 30s
[10:30:04 INF] placement tables updated, version: 0
[10:30:04 INF] dapr initialized. Status: Running. Init Elapsed 149.1871ms
[10:30:04 INF] Dapr Process Status Change: Starting -> Started
[10:30:04 INF] Caching successful startup options for future restart attempts
[10:30:05 INF] Request starting HTTP/1.1 GET http://localhost:5000/weatherforecast/status
[10:30:05 INF] Executing endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetStatus (ServiceInvocationSample)'
[10:30:05 INF] Route matched with {action = "GetStatus", controller = "WeatherForecast"}. Executing controller action with signature Microsoft.AspNetCore.Mvc.ActionResult GetStatus() on controller ServiceInvocationSample.Controllers.WeatherForecastController (ServiceInvocationSample).
[10:30:05 INF] Executing ObjectResult, writing value of type '<>f__AnonymousType0`2[[Man.Dapr.Sidekick.Process.DaprProcessInfo, Man.Dapr.Sidekick, Version=1.0.0.0, Culture=neutral, PublicKeyToken=740d643db1ccf811],[Man.Dapr.Sidekick.DaprSidecarOptions, Man.Dapr.Sidekick, Version=1.0.0.0, Culture=neutral, PublicKeyToken=740d643db1ccf811]]'.
[10:30:05 INF] Executed action ServiceInvocationSample.Controllers.WeatherForecastController.GetStatus (ServiceInvocationSample) in 31.7086ms
[10:30:05 INF] Executed endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetStatus (ServiceInvocationSample)'
[10:30:05 INF] Request finished in 135.4554ms 200 application/json; charset=utf-8
[10:30:05 INF] Request starting HTTP/1.1 GET http://localhost:5000/favicon.ico
[10:30:05 INF] Request finished in 5.4471ms 404
[10:30:15 INF] Request starting HTTP/1.1 GET http://localhost:5000/weatherforecast
[10:30:15 INF] Executing endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.Get (ServiceInvocationSample)'
[10:30:15 INF] Route matched with {action = "Get", controller = "WeatherForecast"}. Executing controller action with signature System.Collections.Generic.IEnumerable`1[ServiceInvocationSample.WeatherForecast] Get() on controller ServiceInvocationSample.Controllers.WeatherForecastController (ServiceInvocationSample).
[10:30:15 INF] Executing ObjectResult, writing value of type 'ServiceInvocationSample.WeatherForecast[]'.
[10:30:15 INF] Executed action ServiceInvocationSample.Controllers.WeatherForecastController.Get (ServiceInvocationSample) in 10.449ms
[10:30:15 INF] Executed endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.Get (ServiceInvocationSample)'
[10:30:15 INF] Request finished in 32.037ms 200 application/json; charset=utf-8
[10:30:21 INF] Request starting HTTP/1.1 GET http://localhost:5000/weatherforecast/sidecar
[10:30:21 INF] Executing endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample)'
[10:30:21 INF] Route matched with {action = "GetViaSidecar", controller = "WeatherForecast"}. Executing controller action with signature System.Threading.Tasks.Task`1[System.Collections.Generic.IEnumerable`1[ServiceInvocationSample.WeatherForecast]] GetViaSidecar() on controller ServiceInvocationSample.Controllers.WeatherForecastController (ServiceInvocationSample).
[10:30:21 INF] Executed action ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample) in 56.5386ms
[10:30:21 INF] Executed endpoint 'ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar (ServiceInvocationSample)'
[10:30:21 ERR] An unhandled exception has occurred while executing the request.
System.Net.Http.HttpRequestException: Response status code does not indicate success: 403 (Forbidden).
   at System.Net.Http.HttpResponseMessage.EnsureSuccessStatusCode()
   at System.Net.Http.HttpClient.GetStringAsyncCore(Task`1 getTask)
   at ServiceInvocationSample.Controllers.WeatherForecastController.GetViaSidecar() in C:\temp\dapr-sidekick-dotnet\samples\AspNetCore\ServiceInvocationSample\ServiceInvocationSample\Controllers\WeatherForecastController.cs:line 70
   at lambda_method(Closure , Object )
   at Microsoft.Extensions.Internal.ObjectMethodExecutorAwaitable.Awaiter.GetResult()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.AwaitableObjectResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Diagnostics.DeveloperExceptionPageMiddleware.Invoke(HttpContext context)
[10:30:21 INF] Request finished in 178.6781ms 500 text/html; charset=utf-8
[10:30:21 INF] Request starting HTTP/1.1 GET http://localhost:5000/_framework/aspnetcore-browser-refresh.js
[10:30:21 INF] Request finished in 3.8585ms 200 application/javascript; charset=utf-8
[10:30:21 INF] Request starting HTTP/1.1 GET http://localhost:5000/_framework/aspnetcore-browser-refresh.js
[10:30:21 INF] Request finished in 2.3403ms 200 application/javascript; charset=utf-8

This is what I get from the status endpoint

I also tried the consul sample, it produces the same 403 response when calling the other service via var httpClient = _httpClientFactory.CreateInvokeHttpClient("consulsample-receiver"); .

badgeratu commented 2 years ago

I can only apologise but I simply cannot reproduce this on either Windows 10 or 11. My latest attempt to reproduce involved the following:

Created a completely clean Windows 11 Pro x64 Hyper-V machine with nested virtualization
Installed WSL2 and Docker Desktop
Installed VS2022 with all the .NET Framework compatibility packs
Installed Dapr CLI 1.5.0 and ran dapr init.
Cloned the dapr-sidekick-dotnet repository and opened the all.sln in VS2022.
Restored all packages and ran a full rebuild - no issues.
Set the Startup Project to ServiceInvocationSample project and pressed F5 to run.
Everything started up normally, no errors from daprd.exe.
Navigated to http://localhost:5000/weatherforecast in Edgium and got a valid forecast JSON result.
Navigated to http://localhost:5000/weatherforecast/sidecar in Edgium and got a valid forecast JSON result via the sidecar.

I'm therefore confident there's not a fundamental issue with Sidekick. What I also don't understand though is how you are getting 404 errors when there's no authentication/authorization anywhere in the sample. I'm really at a loss here :(

larserikfinholt commented 2 years ago

Thanks again for looking into this. I'll continue my dapr testing in a few weeks, but until then suggest we close this, and I'll post an update on my next attempt.

man-group / dapr-sidekick-dotnet

ServiceInvocationSample - error when using CreateInvokeHttpClient #33