gRPC Server does not start, 0.47 upgrade

[cbrit]

I've been trying to upgrade our chain to SDK 0.47, to start I am going through the upgrade steps in this repo that has a module we depend on in sommelier (fork of Gravity).

The issue I'm having is that the gRPC server seems to not be starting after making the recommended service registration changes. The app.toml has gRPC enable on port 9090. Using grpcurl errors saying the server does not support reflection, and our sidecar processes that query the chain are unable to establish a connection. The query routes seem to at least be wired correctly as RPC queries via the CLI are working. I've been stuck on this for a while, has anyone seen this issue before?

The WIP branch can be found here:

https://github.com/PeggyJV/gravity-bridge/tree/collin/sdk-0.47

You'll find that I've completed the following steps:

Register queries in RegisterTxService
https://github.com/PeggyJV/gravity-bridge/blob/b2b17ed7053c5982492923864240fdbe8a34ed82/module/app/app.go#L856-L859

Register node service method and gateway routes
https://github.com/PeggyJV/gravity-bridge/blob/b2b17ed7053c5982492923864240fdbe8a34ed82/module/app/app.go#L820-L842

Register module services
https://github.com/PeggyJV/gravity-bridge/blob/b2b17ed7053c5982492923864240fdbe8a34ed82/module/x/gravity/module.go#L125-L129

Implement RegisterGRPCGatewayRoutes
https://github.com/PeggyJV/gravity-bridge/blob/b2b17ed7053c5982492923864240fdbe8a34ed82/module/x/gravity/module.go#L73-L79

I think there were a few other steps I can't remember offhand, but I've had several people look at this and nothing has stood out. Hopefully I'm missing something obvious; help is much appreciated!

[alexanderbez]

Hi @cbrit, by any chance could you post the following:

1. Logs of a node when it immediately starts up (I'd like to see if the gRPC server start is logged)
2. Logs/output of when you try and execute a gRPC query

Also, to be clear, you CAN execute queries against the :1337 HTTP API? e.g. $ curl localhost:1317/...

[cbrit]

Hey @alexanderbez thanks for the reply, I have not found a log that looks like gRPC starting (the Peer error clears up):

4:00PM INF starting node with ABCI Tendermint in-process module=server
4:00PM INF service start impl=multiAppConn module=proxy msg="Starting multiAppConn service"
4:00PM INF service start connection=query impl=localClient module=abci-client msg="Starting localClient service"
4:00PM INF service start connection=snapshot impl=localClient module=abci-client msg="Starting localClient service"
4:00PM INF service start connection=mempool impl=localClient module=abci-client msg="Starting localClient service"
4:00PM INF service start connection=consensus impl=localClient module=abci-client msg="Starting localClient service"
4:00PM INF service start impl=EventBus module=events msg="Starting EventBus service"
4:00PM INF service start impl=PubSub module=pubsub msg="Starting PubSub service"
4:00PM INF service start impl=IndexerService module=txindex msg="Starting IndexerService service"
4:00PM INF ABCI Handshake App Info hash= height=0 module=consensus protocol-version=0 software-version=
4:00PM INF ABCI Replay Blocks appHeight=0 module=consensus stateHeight=0 storeHeight=0
4:00PM INF InitChain chainID=chain-KuPdmQ initialHeight=1 module=server
4:00PM INF initializing blockchain state from genesis.json module=server
4:00PM INF asserting crisis invariants inv=1/12 module=x/crisis name=staking/module-accounts
4:00PM INF asserting crisis invariants inv=2/12 module=x/crisis name=staking/nonnegative-power
4:00PM INF asserting crisis invariants inv=3/12 module=x/crisis name=staking/positive-delegation
4:00PM INF asserting crisis invariants inv=4/12 module=x/crisis name=staking/delegator-shares
4:00PM INF asserting crisis invariants inv=5/12 module=x/crisis name=transfer/total-escrow-per-denom
4:00PM INF asserting crisis invariants inv=6/12 module=x/crisis name=bank/nonnegative-outstanding
4:00PM INF asserting crisis invariants inv=7/12 module=x/crisis name=bank/total-supply
4:00PM INF asserting crisis invariants inv=8/12 module=x/crisis name=gov/module-account
4:00PM INF asserting crisis invariants inv=9/12 module=x/crisis name=distribution/nonnegative-outstanding
4:00PM INF asserting crisis invariants inv=10/12 module=x/crisis name=distribution/can-withdraw
4:00PM INF asserting crisis invariants inv=11/12 module=x/crisis name=distribution/reference-count
4:00PM INF asserting crisis invariants inv=12/12 module=x/crisis name=distribution/module-account
4:00PM INF asserted all invariants duration=1.733333 height=0 module=x/crisis
4:00PM INF created new capability module=ibc name=ports/transfer
4:00PM INF port binded module=x/ibc/port port=transfer
4:00PM INF claimed capability capability=1 module=transfer name=ports/transfer
4:00PM INF Completed ABCI Handshake - CometBFT and App are synced appHash="���B��\x1c\x14���șo�$'�A�d��L���\x1bxR�U" appHeight=0 module=consensus
4:00PM INF Version info abci=1.0.0 block=11 commit_hash= module=server p2p=8 tendermint_version=0.37.4
4:00PM INF This node is a validator addr=D3CA608470D34E8D4D9388A5075D04710F82E4AB module=consensus pubKey=PubKeyEd25519{12DF1F5ED45209D962A129D0546E03AD83F848344E0715E8147CFF66F32A7E0B}
4:00PM INF P2P Node ID ID=aa765df6b5563aa4f79208f8a56bcd107e0f996c file=/root/.gravity/config/node_key.json module=p2p
4:00PM INF Adding persistent peers addrs=["f5dd9a4beaaa8772361866203c319086f20cf589@gravity1:26656","f7eaa5683e053d68fac943699fdd4015187fde13@gravity2:26656","40cf06dff5f108bda13a714e2c47fa56fa63cc9b@gravity3:26
656"] module=p2p
4:00PM ERR Error in peer's address err="error looking up host (gravity3): lookup gravity3 on 127.0.0.11:53: no such host" module=p2p stack=[{"func":"NewLogger.func1","line":"114","source":"logger.go"},{"func":"a
ppendFieldList","line":"80","source":"fields.go"},{"func":"appendFields","line":"21","source":"fields.go"},{"func":"(*Event).Fields","line":"167","source":"event.go"},{"func":"zeroLogWrapper.Error","line":"153",
"source":"logger.go"},{"func":"(*Switch).AddPersistentPeers","line":"582","source":"switch.go"},{"func":"NewNodeWithContext","line":"1020","source":"node.go"},{"func":"NewNode","line":"849","source":"node.go"},{
"func":"startInProcess","line":"372","source":"start.go"},{"func":"StartCmd.func2.2","line":"153","source":"start.go"},{"func":"wrapCPUProfile.func2","line":"617","source":"start.go"},{"func":"goexit","line":"12
22","source":"asm_arm64.s"}]
4:00PM INF Adding unconditional peer ids ids=[] module=p2p
4:00PM INF Add our address to book addr=aa765df6b5563aa4f79208f8a56bcd107e0f996c@192.168.112.3:26656 book=/root/.gravity/config/addrbook.json module=p2p
4:00PM INF Add our address to book addr=aa765df6b5563aa4f79208f8a56bcd107e0f996c@0.0.0.0:26656 book=/root/.gravity/config/addrbook.json module=p2p
4:00PM INF service start impl=Node module=server msg="Starting Node service"
4:00PM INF service start impl="P2P Switch" module=p2p msg="Starting P2P Switch service"
4:00PM INF service start impl=PEX module=pex msg="Starting PEX service"
4:00PM INF service start book=/root/.gravity/config/addrbook.json impl=AddrBook module=p2p msg="Starting AddrBook service"
4:00PM INF serve module=rpc-server msg="Starting RPC HTTP server on [::]:26657"
4:00PM INF service start impl=Reactor module=blockchain msg="Starting Reactor service"
4:00PM INF service start impl=BlockPool module=blockchain msg="Starting BlockPool service"
4:00PM INF Ensure peers module=pex numDialing=0 numInPeers=0 numOutPeers=0 numToDial=10
4:00PM INF No addresses to dial. Falling back to seeds module=pex
4:00PM INF service start impl=ConsensusReactor module=consensus msg="Starting Consensus service"
4:00PM INF Reactor  module=consensus waitSync=true
4:00PM INF service start impl=Evidence module=evidence msg="Starting Evidence service"
4:00PM INF service start impl=StateSync module=statesync msg="Starting StateSync service"
4:00PM INF Saving AddrBook to file book=/root/.gravity/config/addrbook.json module=p2p size=3
4:00PM INF starting API server... module=api-server
4:00PM INF serve module=api-server msg="Starting RPC HTTP server on 127.0.0.1:1317"
4:00PM INF service start impl="Peer{MConn{192.168.112.6:54128} 40cf06dff5f108bda13a714e2c47fa56fa63cc9b in}" module=p2p msg="Starting Peer service" peer=40cf06dff5f108bda13a714e2c47fa56fa63cc9b@192.168.112.6:541
28
4:00PM INF service start impl=MConn{192.168.112.6:54128} module=p2p msg="Starting MConnection service" peer=40cf06dff5f108bda13a714e2c47fa56fa63cc9b@192.168.112.6:54128
4:00PM INF service start impl="Peer{MConn{192.168.112.5:37610} f7eaa5683e053d68fac943699fdd4015187fde13 in}" module=p2p msg="Starting Peer service" peer=f7eaa5683e053d68fac943699fdd4015187fde13@192.168.112.5:376
10
4:00PM INF service start impl=MConn{192.168.112.5:37610} module=p2p msg="Starting MConnection service" peer=f7eaa5683e053d68fac943699fdd4015187fde13@192.168.112.5:37610
4:00PM INF service start impl="Peer{MConn{192.168.112.4:26656} f5dd9a4beaaa8772361866203c319086f20cf589 out}" module=p2p msg="Starting Peer service" peer=f5dd9a4beaaa8772361866203c319086f20cf589@192.168.112.4:26
656
4:00PM INF service start impl=MConn{192.168.112.4:26656} module=p2p msg="Starting MConnection service" peer=f5dd9a4beaaa8772361866203c319086f20cf589@192.168.112.4:26656
4:00PM INF Time to switch to consensus reactor! height=1 module=blockchain
4:00PM INF service stop impl=BlockPool module=blockchain msg="Stopping BlockPool service"
4:00PM INF SwitchToConsensus module=consensus
4:00PM INF service start impl=ConsensusState module=consensus msg="Starting State service"
4:00PM INF service start impl=baseWAL module=consensus msg="Starting baseWAL service" wal=/root/.gravity/data/cs.wal/wal
4:00PM INF service start impl=Group module=consensus msg="Starting Group service" wal=/root/.gravity/data/cs.wal/wal
4:00PM INF service start impl=TimeoutTicker module=consensus msg="Starting TimeoutTicker service"
4:00PM INF Searching for height height=1 max=0 min=0 module=consensus wal=/root/.gravity/data/cs.wal/wal
4:00PM INF Searching for height height=0 max=0 min=0 module=consensus wal=/root/.gravity/data/cs.wal/wal
4:00PM INF Found height=0 index=0 module=consensus wal=/root/.gravity/data/cs.wal/wal
4:00PM INF Catchup by replaying consensus messages height=1 module=consensus
4:00PM INF Replay: Done module=consensus
4:00PM INF Timed out dur=-1198.856418 height=1 module=consensus round=0 step=RoundStepNewHeight
4:00PM INF commit is for a block we do not know about; set ProposalBlock=nil commit=5A3E291780F8FD0A4C526C46F9FCF4B2D8B3CEC189ECC4DB94580B09568BFC82 commit_round=0 height=1 module=consensus proposal=
4:00PM INF received complete proposal block hash=5A3E291780F8FD0A4C526C46F9FCF4B2D8B3CEC189ECC4DB94580B09568BFC82 height=1 module=consensus
4:00PM INF finalizing commit of block hash=5A3E291780F8FD0A4C526C46F9FCF4B2D8B3CEC189ECC4DB94580B09568BFC82 height=1 module=consensus num_txs=0 root=E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B8
55
4:00PM INF minted coins from module account amount=164778testgb from=mint module=x/bank           

the gRPC error in our sidecar client:

RequestError { error: Status { code: Unimplemented, message: "unknown service cosmos.base.tendermint.v1beta1.Service", metadata: MetadataMap { headers: {"content-type": "application/grpc"} } } }

the gRPC error with grpcurl using reflection:

➜ grpcurl --plaintext localhost:9090 list
Failed to list services: server does not support the reflection API

➜ grpcurl --plaintext -d {} 0.0.0.0:9090 gravity.v1.Query/Params
Error invoking method "gravity.v1.Query/Params": failed to query for service descriptor "gravity.v1.Query": server does not support the reflection API

without reflection:

➜ grpcurl --plaintext -import-path ./module/proto/ -import-path ./module/third_party/proto -proto "gravity/v1/query.proto" 0.0.0.0:9090 gravity.v1.Query/Params
ERROR:
  Code: Unimplemented
  Message: unknown service gravity.v1.Query

as for the API I'm not confident my query is correct but:

➜ curl -X GET http://0.0.0.0:1317/gravity/v1/params
curl: (56) Recv failure: Connection reset by peer

➜ curl -X GET http://0.0.0.0:1317/gravity/gravity/v1/params
curl: (56) Recv failure: Connection reset by peer

the port is open on the container:

5c4d78369703   gravity:prebuilt        "gravity start --tra…"   7 minutes ago   Up 7 minutes   0.0.0.0:1317->1317/tcp, 0.0.0.0:9090->9090/tcp, 0.0.0.0:26656-26657->26656-26657/tcp                   gravity0

I CAN execute queries with the chain CLI:

➜ gravity q gravity params --node http://localhost:26657
params:
  average_block_time: "1000"
  average_ethereum_block_time: "1000"
  bridge_chain_id: "0"
  bridge_ethereum_address: 0x04C89607413713Ec9775E14b954286519d836FEf
  confirmed_outgoing_tx_window: "1000000"
  contract_source_hash: ""
  ethereum_event_vote_window: "5000"
  ethereum_signatures_window: "10000"
  gravity_id: gravitytest
  signed_batches_window: "10000"
  signed_signer_set_txs_window: "10000"
  slash_fraction_batch: "0.001000000000000000"
  slash_fraction_conflicting_ethereum_signature: "0.001000000000000000"
  slash_fraction_ethereum_signature: "0.001000000000000000"
  slash_fraction_signer_set_tx: "0.001000000000000000"
  target_eth_tx_timeout: "3600000"
  unbond_slashing_signer_set_txs_window: "10000"

and the proto:

https://github.com/PeggyJV/gravity-bridge/blob/b2b17ed7053c5982492923864240fdbe8a34ed82/module/proto/gravity/v1/query.proto#L2-L23

[tac0turtle]

hey thanks for helping with the script, both grpc and rest api work out of the box for me. I had to enable the rest api since it was defaulted to off in the toml. Im not sure what you were doing differently, maybe something with the docker setup?

[cbrit]

Thank you for the help. I've fixed it now and the cause seems to be twofold:

1. We were using the image golang:alpine, but had changed the pinned go version for the app, and apparently there was an incompatibility. Instead of failing to build or run, it was just silently killing gRPC? I still don't understand why this happened. By pinning to an image that uses the same go version I was able to to get gRPC working from inside the container.
2. Even though there seem to be no changes in the app.toml between SDK version, leaving the gRPC address as the default "localhost" was making the app inaccessible outside of the container. Manually changing it to 0.0.0.0 in the test setup fixed it. I don't know if something was making that change automatically in the past or what.

Thank you for the help @tac0turtle