search

dapr / js-sdk

Dapr SDK for Javascript
Apache License 2.0
192 stars 80 forks source link

"http2: frame too large" when using PubSub with GRPC #561

Closed brunoshine closed 7 months ago

brunoshine commented 7 months ago

Expected Behavior

In this simple example I'm using the DaprServer to get a configuration key and also subscribe to a pubsub topic. Because Configuration requires GRPC, the ClientOptions sets the communication to grpc

import { DaprServer, CommunicationProtocolEnum } from '@dapr/dapr';
const server = new DaprServer({
    clientOptions: {
        communicationProtocol: CommunicationProtocolEnum.GRPC
    }
});

const configs = await server.client.configuration.get("configuration", ["key"])

server.pubsub.subscribe("pubsub", "teste", async (data, headers) =>
    console.log("Subscriber received: " + JSON.stringify(data))
);

await server.start();

To run this I'm using:

dapr run --app-id order-processing --app-port 5002 --dapr-http-port 3501   --app-protocol grpc --resources-path .dapr/components/ -- node server.js

The pubsub component definition is:

apiVersion: dapr.io/v1alpha1
kind: Component
metadata:
  name: pubsub
spec:
  type: pubsub.redis
  version: v1
  metadata:
  - name: redisHost
    value: localhost:6379
  - name: redisPassword
    value: ""

Actual Behavior

When running I get an immediate error:

> dapr run --app-id order-processing --app-port 5002 --dapr-http-port 3501   --app-protocol grpc --resources-path .dapr/components/ -- node server.js

ℹ️  Starting Dapr with id order-processing. HTTP Port: 3501. gRPC Port: 40917
INFO[0000] Starting Dapr Runtime -- version 1.12.2 -- commit f954254ed520409602024ea6d507d0405afa1f07  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] Log level set to: info                        app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
WARN[0000] mTLS is disabled. Skipping certificate request and tls validation  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.security type=log ver=1.12.2
INFO[0000] metrics server started on :33047/             app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] standalone mode configured                    app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] app id: order-processing                      app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] Dapr trace sampler initialized: DaprTraceSampler(P=1.000000)  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] local service entry announced: order-processing -> 172.26.111.23:42347  app_id=order-processing component="mdns (nameResolution/v1)" instance=LIS-KN0084194 scope=dapr.contrib type=log ver=1.12.2
INFO[0000] Initialized name resolution to mdns           app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] Loading components…                           app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] Component loaded: configuration (configuration.redis)  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] Component loaded: pubsub (pubsub.redis/v1)    app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] Waiting for all outstanding components to be processed…  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] Using 'statestore' as actor state store       app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.processor.state type=log ver=1.12.2
INFO[0000] Component loaded: statestore (state.redis/v1)  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] All outstanding components processed          app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] Loading endpoints…                            app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] Waiting for all outstanding http endpoints to be processed…  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] All outstanding http endpoints processed      app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] gRPC server listening on TCP address: :40917  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.grpc.api type=log ver=1.12.2
INFO[0000] Enabled gRPC tracing middleware               app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.grpc.api type=log ver=1.12.2
INFO[0000] Enabled gRPC metrics middleware               app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.grpc.api type=log ver=1.12.2
INFO[0000] Registering workflow engine for gRPC endpoint: [::]:40917  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.grpc.api type=log ver=1.12.2
INFO[0000] API gRPC server is running on port 40917      app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] Enabled max body size HTTP middleware with size 4 MB  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.http type=log ver=1.12.2
INFO[0000] Enabled tracing HTTP middleware               app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.http type=log ver=1.12.2
INFO[0000] Enabled metrics HTTP middleware               app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.http type=log ver=1.12.2
INFO[0000] HTTP server listening on TCP address: :3501   app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.http type=log ver=1.12.2
INFO[0000] HTTP server is running on port 3501           app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] The request body size parameter is: 4         app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] gRPC server listening on TCP address: :42347  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.grpc.internal type=log ver=1.12.2
INFO[0000] Enabled gRPC tracing middleware               app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.grpc.internal type=log ver=1.12.2
INFO[0000] Enabled gRPC metrics middleware               app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.grpc.internal type=log ver=1.12.2
INFO[0000] Internal gRPC server is running on port 42347  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] application protocol: grpc. waiting on port 5002.  This will block until the app is listening on that port.  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
== APP == 2023-12-13T23:04:59.234Z INFO [GRPCClient, GRPCClient] Opening connection to 127.0.0.1:40917
WARN[0000] redis key key does not exist, ignore it       app_id=order-processing component="configuration (configuration.redis)" instance=LIS-KN0084194 scope=dapr.contrib type=log ver=1.12.2
== APP == 2023-12-13T23:04:59.281Z INFO [HTTPServer, HTTPServerImpl] [Topic = teste] Registered Subscription with routes: default
== APP == 2023-12-13T23:04:59.283Z INFO [HTTPServer, HTTPServer] Listening on 5002
== APP == 2023-12-13T23:04:59.284Z INFO [HTTPServer, HTTPServer] Registering 1 PubSub Subscriptions
INFO[0000] application discovered on port 5002           app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] Actor runtime started. Actor idle timeout: 1h0m0s. Actor scan interval: 30s  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.actor type=log ver=1.12.2
INFO[0000] Configuring workflow engine with actors backend  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.wfengine type=log ver=1.12.2
INFO[0000] Registering component for dapr workflow engine...  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] Initializing Dapr workflow component          app_id=order-processing component="dapr (workflow.dapr/v1)" instance=LIS-KN0084194 scope=dapr.contrib type=log ver=1.12.2
INFO[0000] Error processing operation DaprBuiltInInitializationRetries. Retrying in 369.423342ms…  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2
INFO[0000] Placement tables updated, version: 0          app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.actors.placement type=log ver=1.12.2
ℹ️  Updating metadata for appPID: 15058
ℹ️  Updating metadata for app command: node server.js
✅  You're up and running! Both Dapr and your app logs will appear here.

ERRO[0002] error getting topic list from app: rpc error: code = Unavailable desc = connection error: desc = "error reading server preface: http2: frame too large"  app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime.processor.pubsub type=log ver=1.12.2
WARN[0002] failed to subscribe to topics: error occurred while beginning pubsub pubsub: rpc error: code = Unavailable desc = connection error: desc = "error reading server preface: http2: frame too large"   app_id=order-processing instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2

Steps to Reproduce the Problem

Simply add the package @dapr/dapr version ^3.2.0 and run the above code

shubham1172 commented 7 months ago

Hi there @brunoshine, the problem is that you are setting the client's communication protocol, not the server's. There are two different communications here.

  1. Dapr sidecar to your application (your app acts as a server, server protocol)
  2. Application to Dapr sidecar (your app acts as a client, client protocol) 
import { DaprServer, CommunicationProtocolEnum } from '@dapr/dapr';
const server = new DaprServer({
    // This is important
    communicationProtocol: CommunicationProtocolEnum.GRPC,
    // This is optional, since by-default client will use whatever protocol server is configured with.
    // Only useful if you want the client to use a different protocol than server
    clientOptions: {
        communicationProtocol: CommunicationProtocolEnum.GRPC
    }
});

Docs https://docs.dapr.io/developing-applications/sdks/js/js-server/

shubham1172 commented 7 months ago

Hope the above is clear, please let me know if you are still running into any issues, closing for now!

brunoshine commented 7 months ago

Hi @shubham1172 Thank you so much for the quick response. It worked :) Somehow I missed the server configuration part. Cheers.

brunoshine commented 7 months ago

By the way, sometimes I get this error:

ERRO[0005] error getting topic list from app: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:3500: connect: connection refused"  app_id=ms-azure-face-api instance=LIS-KN0084194 scope=dapr.runtime.processor.pubsub type=log ver=1.12.2
WARN[0005] failed to subscribe to topics: error occurred while beginning pubsub pubsub: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:3500: connect: connection refused"   app_id=ms-azure-face-api instance=LIS-KN0084194 scope=dapr.runtime type=log ver=1.12.2

Also the pubsub seems inconsistent. Sometimes the server gets the subscribed messages, other it dosen't. :/

Any thoughts? Thanks

shubham1172 commented 7 months ago

@brunoshine can you share the command used to run Dapr and app? And logs from app + dapr sidecar?

brunoshine commented 7 months ago

The commands are:

"scripts": {
    "client": "dapr run --app-id checkout --dapr-http-port 3502   --app-protocol grpc --resources-path .dapr/components/ -- node client.js",
    "server": "dapr run --app-id order-processing --app-port 5002 --dapr-http-port 3501   --app-protocol grpc --resources-path .dapr/components/ -- node server.js"
  },

The error error getting topic list from app: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:3500: connect: connection refused" I only get it from time to time.

shubham1172 commented 7 months ago

Could you share all the logs? Or better, you can ping me on Dapr Discord under #pubsub, https://aka.ms/dapr-discord

shubham1172 commented 7 months ago

From a chat with @brunoshine offline, this issue is no longer reproducible by them.