dotnet subscriber unable to receive published message from controller post method

[htzhang2]

Enviornment: Windows 10 vm dapr AspNetCore 0.11.0-preview 2

[app_root_folder]\Components\subscription.yaml: apiVersion: dapr.io/v1alpha1 kind: Subscription metadata: name: pubsub spec: topic: newOrder route: /newOrderCreated pubsubname: pubsub

Controller code: [HttpPost] [Route("newOrderCreated")] public ActionResult AddPayment( [FromBody] Payment paymentItem) { Console.WriteLine("New order arrived for {0} {1} {2} {3}", paymentItem.Item, paymentItem.Count, paymentItem.Total);

        payments.Add(paymentItem);
        return this.Ok(paymentItem);
    }

Powershell command: dapr run --app-id paymentService --components-path .\Components\ --log-level debug --app-port 5050 --dapr-http-port 5055 dotnet run

Expected: controller method with Route('/newOrderCreated is called when message published

Actual: controller method is NOT called when message is published

Log: Starting Dapr with id paymentService. HTTP Port: 5055. gRPC Port: 62616 ←[93;1m== DAPR == time="2020-11-23T18:50:23.08916Z" level=info msg="starting Dapr Runtime -- version 0.11.3 -- commit a1a8e11" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:23.08916Z" level=info msg="log level set to: debug" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:23.090154Z" level=info msg="metrics server started on :62617/" app_id=paymentService instance=zhang-vm scope=dapr.metrics type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:23.0961647Z" level=debug msg="No Access control policy specified" app_id=paymentService instance=zhang-vm scope=dapr.configuration type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:23.0961647Z" level=info msg="standalone mode configured" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:23.0961647Z" level=info msg="app id: paymentService" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:23.0961647Z" level=info msg="mTLS is disabled. Skipping certificate request and tls validation" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:23.0961647Z" level=info msg="application protocol: http. waiting on port 5050. This will block until the app is listening on that port." app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[94;1m== APP == info: Microsoft.Hosting.Lifetime[0] ←[0m ←[94;1m== APP == Now listening on: https://localhost:5003 ←[0m ←[94;1m== APP == info: Microsoft.Hosting.Lifetime[0] ←[0m ←[94;1m== APP == Now listening on: http://localhost:5050 ←[0m ←[94;1m== APP == info: Microsoft.Hosting.Lifetime[0] ←[0m ←[94;1m== APP == Application started. Press Ctrl+C to shut down. ←[0m ←[94;1m== APP == info: Microsoft.Hosting.Lifetime[0] ←[0m ←[94;1m== APP == Hosting environment: Development ←[0m ←[94;1m== APP == info: Microsoft.Hosting.Lifetime[0] ←[0m ←[94;1m== APP == Content root path: C:\repos\vwac\Research\VWAC.Research\Teams\Outliner\dapr\dapr.payment.service\dapr.payment.service ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.8815162Z" level=info msg="application discovered on port 5050" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9475098Z" level=info msg="application configuration loaded" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9585236Z" level=info msg="local service entry announced: paymentService -> 172.16.45.4:62623" app_id=paymentService instance=zhang-vm scope=dapr.contrib type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9585236Z" level=info msg="Initialized name resolution to standalone" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9605098Z" level=info msg="waiting for all outstanding components to be processed" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9605098Z" level=info msg="component loaded. name: pubsub, type: " app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9605098Z" level=info msg="all outstanding components processed" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9605098Z" level=warning msg="actors: state store must be present to initialize the actor runtime" app_id=paymentService instance=zhang-vm scope=dapr.runtime.actor type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9605098Z" level=warning msg="failed to init actors: state store does not support transactions which actors require to save state - please see https://github.com/dapr/docs" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9615128Z" level=info msg="enabled gRPC tracing middleware" app_id=paymentService instance=zhang-vm scope=dapr.runtime.grpc.api type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9615128Z" level=info msg="API gRPC server is running on port 62616" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9615128Z" level=info msg="enabled gRPC tracing middleware" app_id=paymentService instance=zhang-vm scope=dapr.runtime.grpc.internal type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9625126Z" level=info msg="internal gRPC server is running on port 62623" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9635084Z" level=info msg="enabled cors http middleware" app_id=paymentService instance=zhang-vm scope=dapr.runtime.http type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9635084Z" level=info msg="enabled tracing http middleware" app_id=paymentService instance=zhang-vm scope=dapr.runtime.http type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9635084Z" level=info msg="http server is running on port 5055" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m ←[93;1m== DAPR == time="2020-11-23T18:50:25.9635084Z" level=info msg="dapr initialized. Status: Running. Init Elapsed 2867.3437000000004ms" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3 ←[0m Updating metadata for app command: dotnet run You're up and running! Both Dapr and your app logs will appear here.

[htzhang2]

publisher url: http://localhost:5025/v1.0/publish/pubsub/newOrder

[yaron2]

Transferred issue to Dotnet SDK repo. @rynowak @vinayada1 can you assist?

[vinayada1]

@htzhang2 - Could you add the Topic attribute as in the sample: https://github.com/dapr/dotnet-sdk/blob/47b59b4a97f73a386d74fa900effd06527735224/samples/AspNetCore/ControllerSample/Controllers/SampleController.cs#L67

[htzhang2]

I did add, still not receiving the message:

    [Topic("pubsub", "newOrder")]
    [HttpPost]
    [Route("/newOrderCreated")]
    public ActionResult<Payment> AddPayment(
        [FromBody] Payment paymentItem)
    {

[vinayada1]

@htzhang2 - Could you please share your code in Startup.cs. Also, could you try the publish via the CLI and see if it is working as mentioned in the sample:

Withdraw Money (pubsub)

Publish events using Dapr cli:

On Linux, MacOS:

dapr publish --pubsub pubsub -t withdraw -d '{"id": "17", "amount": 15 }' On Windows:

dapr publish --pubsub pubsub -t withdraw -d "{\"id\": \"17\", \"amount\": 15 }"

[htzhang2]

public class Startup
{
    public Startup(IConfiguration configuration)
    {
        Configuration = configuration;
    }

    public IConfiguration Configuration { get; }

    // This method gets called by the runtime. Use this method to add services to the container.
    public void ConfigureServices(IServiceCollection services)
    {
        services.AddCors(o => o.AddPolicy("MyPolicy", builder =>
        {
            builder.AllowAnyOrigin()
                   .AllowAnyMethod()
                   .AllowAnyHeader();
        }));

        services.AddControllers().AddDapr();

    }

    // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
    public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
    {
        if (env.IsDevelopment())
        {
            app.UseDeveloperExceptionPage();
        }

        app.UseHttpsRedirection();

        app.UseRouting();

        app.UseCloudEvents();

        app.UseCors("MyPolicy");

        app.UseAuthorization();      

        app.UseEndpoints(endpoints =>
        {
            endpoints.MapSubscribeHandler();
            endpoints.MapControllers();
        });
    }
}

[htzhang2]

$ dapr publish --pubsub pubsub -t newOrder -d "{"Key":"volkswagen-golf-2021","Item":"volkswagen-golf-2021","Count":"1","Total":20000}" Event published successfully

[vinayada1]

The Startup.cs code looks okay. Also, was your subscriber able to see the event published using dapr cli command? If yes, then the issue seems to be with the publisher. You could try publishing to the Dapr endpoint: http://localhost:/v1.0/publish// directly using a rest client such as Postman. Let's see if that works.

[htzhang2]

No. Subscriber can't see event published with dapr cli command

[victormarante]

@htzhang2 Hi, do you receive any logs from your .NET application when you publish the event? Can you try and set log level to default information from all sources, publish event and share logs from API, if any show up that is.

[htzhang2]

Publisher log looks fine:

←[94;1m== APP == info: System.Net.Http.HttpClient.IPublishService.LogicalHandler[100] ←[0m ←[94;1m== APP == Start processing HTTP request POST http://localhost:5025/v1.0/publish/pubsub/newOrder ←[0m ←[94;1m== APP == info: System.Net.Http.HttpClient.IPublishService.ClientHandler[100] ←[0m ←[94;1m== APP == Sending HTTP request POST http://localhost:5025/v1.0/publish/pubsub/newOrder ←[0m ←[94;1m== APP == info: System.Net.Http.HttpClient.IPublishService.ClientHandler[101] ←[0m ←[94;1m== APP == Received HTTP response after 2080.015ms - OK ←[0m ←[94;1m== APP == info: System.Net.Http.HttpClient.IPublishService.LogicalHandler[101] ←[0m ←[94;1m== APP == End processing HTTP request after 2091.8117ms - OK ←[0m ←[94;1m== APP == Publish new order successfully

[htzhang2]

node subscriber can receive message from same publisher.

Something with dotnet subscriber.

[vinayada1]

If you add the [Topic...] attribute to your subscriber code, then you should see logs similar to these at startup:- == DAPR == time="2020-12-03T14:22:24.162915-08:00" level=info msg="app is subscribed to the following topics: [deposit withdraw] through pubsub=pubsub" app_id=controller instance=Pacha.redmond.corp.microsoft.com scope=dapr.runtime type=log ver=1.0.0-rc.1

I don't see this in the logs that you have pasted. Could you try comparing your code with the Controller Sample and see what is different.

[htzhang2]

Right, there is no such log in dotnet subscriber. But nodejs subscriber has similar log.

I didn't see anything different from sample controller.

Could it be something wrong in actor state store?

←[93;1m== DAPR == time="2020-12-03T23:18:32.3358265Z" level=warning msg="failed to init actors: state store does not support transactions which actors require to save state - please see https://github.com/dapr/docs" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3

[htzhang2]

If copy both pubsub.yaml and subscription.yaml under same folder (.\Components), then dotnet subscription log shows up.

However, an error occurred when a message arrives:

←[93;1m== DAPR == time="2020-12-03T23:46:53.7467606Z" level=warning msg="retriable error returned from app while processing pub/sub event 7cc24661-a016-4932-9bc4-244a61ff6bfd: . status code returned: 307" app_id=paymentService instance=zhang-vm scope=dapr.runtime type=log ver=0.11.3

[vinayada1]

From the error, the issue seems to be in the application code. Could you add logs/breakpoint to your AddPayment method? Make sure the code is entering this method when a message is published and then debug further.

[vinayada1]

@htzhang2 - Is this still an issue?

[htzhang2]

Yes. Still an issue

[vinayada1]

@htzhang2 - Could you refer to https://github.com/dapr/dotnet-sdk/blob/master/docs/troubleshooting-pub-sub.md and try to see if you can find the issue? Potentially...app.UseHttpsRedirection(); might be the culprit.

[vinayada1]

@htzhang2 - Were you able to debug the issue?

[rynowak]

Closing due to lack of response

[MatiKloster]

@htzhang2 - Could you refer to https://github.com/dapr/dotnet-sdk/blob/master/docs/troubleshooting-pub-sub.md and try to see if you can find the issue? Potentially...app.UseHttpsRedirection(); might be the culprit.

Removing HttpsRedirection definitely did the trick. Hours with this the same error... thank god I reached here

Thanks

[vinz6751]

I was having the same issue using two WebApi services running as Docker containers, and their sidecars running as containers as well using Visual Studio's Docker Compose support. The log contained " app returned http status code 307 from subscription endpoint". I disabled app.UseHttpsRedirection(); in the startup then everything started working. Thank you for the trick!