gRPC stability
h4sh3d opened this issue · 6 comments
h4sh3d commented
gRPC is now working with all calls, but when multiple calls happen at the same time, e.g. health check and other, we can see lines like this multiple times
[2022-12-19T13:11:40Z ERROR microservices::esb::controller] ESB request processing error: Farcaster node errors: sending on a closed channel
h4sh3d commented
Only working fix seems to restart farcasterd (didn't try to just restart grpcd yet)
TheCharlatan commented
Thanks for reporting! When I get the time, I'll add a grpc test for multiple, concurrent calls.
h4sh3d commented
Looks like this only affects calls related to syncers (or other services maybe), I'm currently having this state but decoding deals works perfectly fine.
TheCharlatan commented
I wrote a test that concurrently mixes 10 info and 10 health_check requests and have not run into this issue. Do you happen to have a bit more logging than the line you posted?
h4sh3d commented
So, more thinking into this this morning :)
Here are more logs (~10 secs of running the node with the GUI)
[2022-12-20T07:21:58Z DEBUG farcaster_node::grpcd::runtime] Received a grpc info request: Request { metadata: MetadataMap { headers: {"host": "localhost:50051", "user-agent": "Mozilla/5.0 (X11; Linux x86_64; rv:107.0) Gecko/20100101 Firefox/107.0", "accept": "application/grpc-web-text", "accept-language": "en-US,en;q=0.5", "accept-encoding": "identity,deflate,gzip", "content-type": "application/grpc", "x-user-agent": "grpc-web-javascript/0.1", "x-grpc-web": "1", "sec-fetch-site": "same-site", "origin": "http://localhost:3000", "connection": "keep-alive", "referer": "http://localhost:3000/", "sec-fetch-dest": "empty", "sec-fetch-mode": "cors", "te": "trailers"} }, message: InfoRequest { id: 0 }, extensions: Extensions }
[2022-12-20T07:21:58Z DEBUG farcaster_node::grpcd::runtime] sending request over grpc bridge: Bridge(Info { request: GetInfo, service_id: Farcasterd })
[2022-12-20T07:21:58Z DEBUG microservices::esb::controller] grpcd_client<20> -> grpcd: Bridge Rpc farcasterd
[2022-12-20T07:21:58Z DEBUG farcaster_node::grpcd::runtime] GRPCD BRIDGE RPC request: Bridge Rpc farcasterd, grpcd_client<20>
[2022-12-20T07:21:58Z DEBUG microservices::esb::controller] grpcd_client<20> -> farcasterd: get_info()
[2022-12-20T07:21:58Z DEBUG microservices::esb::controller] grpcd_client<20> -> grpcd: node_info(..)
[2022-12-20T07:21:58Z DEBUG farcaster_node::service] New service Monero (Testnet) syncer with PID 68441 started
[2022-12-20T07:21:58Z DEBUG microservices::esb::controller] Monero (Testnet) syncer -> farcasterd: hello()
[2022-12-20T07:21:58Z INFO farcaster_node::farcasterd::runtime] Service Monero (Testnet) syncer is now connected
[2022-12-20T07:21:58Z INFO farcaster_node::farcasterd::runtime] Syncer Monero (Testnet) syncer is registered; total 1 syncers are known
[2022-12-20T07:21:58Z INFO farcaster_node::event] Syncer state transition Awaiting Syncer -> Awaiting Syncer Request
[2022-12-20T07:21:58Z DEBUG microservices::esb::controller] farcasterd -> Monero (Testnet) syncer: syncer_task(HealthCheck(HealthCheck { id: TaskId(1) }))
[2022-12-20T07:21:58Z DEBUG farcaster_node::syncerd::monero_syncer] performing health check
[2022-12-20T07:21:58Z INFO farcaster_node::syncerd::syncer_state] Monero | Incremented height 1248968
[2022-12-20T07:21:59Z DEBUG microservices::esb::controller] Monero (Testnet) syncer -> Monero (Testnet) syncer: syncer_bridge_ev(farcasterd, HealthResult(HealthResult { id: TaskId(1), health: Healthy }))
[2022-12-20T07:21:59Z DEBUG farcaster_node::syncerd::runtime] Syncerd BRIDGE RPC request: syncer_bridge_ev(farcasterd, HealthResult(HealthResult { id: TaskId(1), health: Healthy }))
[2022-12-20T07:21:59Z DEBUG microservices::esb::controller] Monero (Testnet) syncer -> farcasterd: syncer_event(HealthResult(HealthResult { id: TaskId(1), health: Healthy }))
[2022-12-20T07:21:59Z INFO farcaster_node::farcasterd::runtime] Terminating Monero (Testnet) syncer
[2022-12-20T07:21:59Z INFO farcaster_node::event] Syncer state machine ended Awaiting Syncer Request -> End
[2022-12-20T07:21:59Z DEBUG microservices::esb::controller] grpcd_client<19> -> grpcd: health_result(Healthy)
[2022-12-20T07:21:59Z DEBUG microservices::esb::controller] farcasterd -> Monero (Testnet) syncer: terminate()
[2022-12-20T07:21:59Z INFO farcaster_node::syncerd::runtime] Received terminate on Monero (Testnet) syncer
[2022-12-20T07:21:59Z ERROR farcaster_node::grpcd::runtime] Error encountered while sending response to Grpc server: health_result(Healthy)
[2022-12-20T07:22:00Z DEBUG farcaster_node::grpcd::runtime] sending request over grpc bridge: Bridge(Ctl { request: HealthCheck(Bitcoin, Testnet), service_id: Farcasterd })
[2022-12-20T07:22:00Z DEBUG microservices::esb::controller] grpcd_client<21> -> grpcd: Bridge Ctl farcasterd
[2022-12-20T07:22:00Z DEBUG farcaster_node::grpcd::runtime] GRPCD BRIDGE RPC request: Bridge Ctl farcasterd, grpcd_client<21>
[2022-12-20T07:22:00Z DEBUG farcaster_node::grpcd::runtime] Received a grpc info request: Request { metadata: MetadataMap { headers: {"host": "localhost:50051", "user-agent": "Mozilla/5.0 (X11; Linux x86_64; rv:107.0) Gecko/20100101 Firefox/107.0", "accept": "application/grpc-web-text", "accept-language": "en-US,en;q=0.5", "accept-encoding": "identity,deflate,gzip", "content-type": "application/grpc", "x-user-agent": "grpc-web-javascript/0.1", "x-grpc-web": "1", "sec-fetch-site": "same-site", "origin": "http://localhost:3000", "connection": "keep-alive", "referer": "http://localhost:3000/", "sec-fetch-dest": "empty", "sec-fetch-mode": "cors", "te": "trailers"} }, message: InfoRequest { id: 0 }, extensions: Extensions }
[2022-12-20T07:22:00Z DEBUG farcaster_node::grpcd::runtime] sending request over grpc bridge: Bridge(Info { request: GetInfo, service_id: Farcasterd })
[2022-12-20T07:22:00Z DEBUG microservices::esb::controller] grpcd_client<21> -> farcasterd: health_check(Bitcoin Testnet)
[2022-12-20T07:22:00Z DEBUG farcaster_node::farcasterd::runtime] launching syncer with: ["--blockchain", "Bitcoin", "--network", "Testnet", "--electrum-server", "ssl://blockstream.info:993"]
[2022-12-20T07:22:00Z DEBUG microservices::esb::controller] grpcd_client<22> -> grpcd: Bridge Rpc farcasterd
[2022-12-20T07:22:00Z DEBUG farcaster_node::grpcd::runtime] GRPCD BRIDGE RPC request: Bridge Rpc farcasterd, grpcd_client<22>
[2022-12-20T07:22:00Z DEBUG farcaster_node::farcasterd::runtime] Launching syncerd as a separate process using `/home/joel/.cargo/bin/syncerd` as binary
[2022-12-20T07:22:00Z DEBUG farcaster_node::farcasterd::runtime] tor opts: None
[2022-12-20T07:22:00Z DEBUG farcaster_node::farcasterd::runtime] Executing `"/home/joel/.cargo/bin/syncerd" "-d" "~/.farcaster" "-m" "{data_dir}/msg" "-x" "{data_dir}/ctl" "-i" "{data_dir}/info" "-S" "{data_dir}/sync" "--blockchain" "Bitcoin" "--network" "Testnet" "--electrum-server" "ssl://blockstream.info:993"`
[2022-12-20T07:22:00Z INFO farcaster_node::event] Syncer state transition Start -> Awaiting Syncer
[2022-12-20T07:22:00Z DEBUG microservices::esb::controller] grpcd_client<22> -> farcasterd: get_info()
[2022-12-20T07:22:00Z DEBUG microservices::esb::controller] grpcd_client<22> -> grpcd: node_info(..)
[2022-12-20T07:22:00Z ERROR microservices::esb::controller] ESB request processing error: Farcaster node errors: sending on a closed channel
[2022-12-20T07:22:00Z INFO farcaster_node::syncerd::runtime] Creating new Bitcoin (Testnet) syncer
[2022-12-20T07:22:00Z DEBUG farcaster_node::syncerd::bitcoin_syncer] bitcoin synclet using proxy: None
[2022-12-20T07:22:00Z DEBUG microservices::esb::controller] Creating ESB session for service MSG located at /home/joel/.farcaster/msg with identity 'Bitcoin (Testnet) syncer'
[2022-12-20T07:22:00Z DEBUG microservices::esb::controller] Creating ESB session for service CTL located at /home/joel/.farcaster/ctl with identity 'Bitcoin (Testnet) syncer'
[2022-12-20T07:22:00Z DEBUG microservices::esb::controller] Creating ESB session for service INFO located at /home/joel/.farcaster/info with identity 'Bitcoin (Testnet) syncer'
[2022-12-20T07:22:00Z DEBUG microservices::esb::controller] Creating ESB session for service SYNC located at /home/joel/.farcaster/sync with identity 'Bitcoin (Testnet) syncer'
[2022-12-20T07:22:00Z DEBUG microservices::esb::controller] Creating ESB session for service BRIDGE
[2022-12-20T07:22:00Z DEBUG farcaster_node::syncerd::bitcoin_syncer] creating ElectrumRpc client
[2022-12-20T07:22:00Z DEBUG farcaster_node::syncerd::bitcoin_syncer] creating ElectrumRpc client
[2022-12-20T07:22:00Z DEBUG farcaster_node::syncerd::bitcoin_syncer] New ElectrumRpc at height 2411974
[2022-12-20T07:22:00Z INFO farcaster_node::syncerd::syncer_state] Bitcoin | Incremented height 2411974
[2022-12-20T07:22:00Z DEBUG farcaster_node::syncerd::bitcoin_syncer] New ElectrumRpc at height 2411974
[2022-12-20T07:22:01Z DEBUG farcaster_node::syncerd::bitcoin_syncer] creating ElectrumRpc client
[2022-12-20T07:22:01Z DEBUG farcaster_node::syncerd::bitcoin_syncer] creating fee polling electrum client
[2022-12-20T07:22:01Z DEBUG farcaster_node::service] New service Bitcoin (Testnet) syncer with PID 68456 started
[2022-12-20T07:22:01Z DEBUG microservices::esb::controller] Bitcoin (Testnet) syncer -> farcasterd: hello()
[2022-12-20T07:22:01Z INFO farcaster_node::farcasterd::runtime] Service Bitcoin (Testnet) syncer is now connected
[2022-12-20T07:22:01Z INFO farcaster_node::farcasterd::runtime] Syncer Bitcoin (Testnet) syncer is registered; total 1 syncers are known
[2022-12-20T07:22:01Z INFO farcaster_node::event] Syncer state transition Awaiting Syncer -> Awaiting Syncer Request
[2022-12-20T07:22:01Z DEBUG microservices::esb::controller] farcasterd -> Bitcoin (Testnet) syncer: syncer_task(HealthCheck(HealthCheck { id: TaskId(2) }))
[2022-12-20T07:22:01Z DEBUG farcaster_node::grpcd::runtime] Received a grpc info request: Request { metadata: MetadataMap { headers: {"host": "localhost:50051", "user-agent": "Mozilla/5.0 (X11; Linux x86_64; rv:107.0) Gecko/20100101 Firefox/107.0", "accept": "application/grpc-web-text", "accept-language": "en-US,en;q=0.5", "accept-encoding": "identity,deflate,gzip", "content-type": "application/grpc", "x-user-agent": "grpc-web-javascript/0.1", "x-grpc-web": "1", "sec-fetch-site": "same-site", "origin": "http://localhost:3000", "connection": "keep-alive", "referer": "http://localhost:3000/", "sec-fetch-dest": "empty", "sec-fetch-mode": "cors", "te": "trailers"} }, message: InfoRequest { id: 0 }, extensions: Extensions }
[2022-12-20T07:22:01Z DEBUG farcaster_node::grpcd::runtime] sending request over grpc bridge: Bridge(Info { request: GetInfo, service_id: Farcasterd })
[2022-12-20T07:22:01Z DEBUG microservices::esb::controller] grpcd_client<23> -> grpcd: Bridge Rpc farcasterd
[2022-12-20T07:22:01Z DEBUG farcaster_node::grpcd::runtime] GRPCD BRIDGE RPC request: Bridge Rpc farcasterd, grpcd_client<23>
[2022-12-20T07:22:01Z DEBUG microservices::esb::controller] grpcd_client<23> -> farcasterd: get_info()
[2022-12-20T07:22:01Z DEBUG microservices::esb::controller] grpcd_client<23> -> grpcd: node_info(..)
[2022-12-20T07:22:01Z ERROR microservices::esb::controller] ESB request processing error: Farcaster node errors: sending on a closed channel
[2022-12-20T07:22:01Z DEBUG farcaster_node::syncerd::bitcoin_syncer] New ElectrumRpc at height 2411974
[2022-12-20T07:22:01Z DEBUG farcaster_node::syncerd::bitcoin_syncer] performing health check
[2022-12-20T07:22:01Z DEBUG farcaster_node::syncerd::bitcoin_syncer] creating ElectrumRpc client
[2022-12-20T07:22:01Z DEBUG farcaster_node::syncerd::bitcoin_syncer] New ElectrumRpc at height 2411974
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] Bitcoin (Testnet) syncer -> Bitcoin (Testnet) syncer: syncer_bridge_ev(farcasterd, HealthResult(HealthResult { id: TaskId(2), health: Healthy }))
[2022-12-20T07:22:02Z DEBUG farcaster_node::syncerd::runtime] Syncerd BRIDGE RPC request: syncer_bridge_ev(farcasterd, HealthResult(HealthResult { id: TaskId(2), health: Healthy }))
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] Bitcoin (Testnet) syncer -> farcasterd: syncer_event(HealthResult(HealthResult { id: TaskId(2), health: Healthy }))
[2022-12-20T07:22:02Z INFO farcaster_node::farcasterd::runtime] Terminating Bitcoin (Testnet) syncer
[2022-12-20T07:22:02Z INFO farcaster_node::event] Syncer state machine ended Awaiting Syncer Request -> End
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] grpcd_client<21> -> grpcd: health_result(Healthy)
[2022-12-20T07:22:02Z ERROR microservices::esb::controller] ESB request processing error: Farcaster node errors: sending on a closed channel
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] farcasterd -> Bitcoin (Testnet) syncer: terminate()
[2022-12-20T07:22:02Z INFO farcaster_node::syncerd::runtime] Received terminate on Bitcoin (Testnet) syncer
[2022-12-20T07:22:02Z DEBUG farcaster_node::grpcd::runtime] sending request over grpc bridge: Bridge(Ctl { request: HealthCheck(Bitcoin, Testnet), service_id: Farcasterd })
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] grpcd_client<24> -> grpcd: Bridge Ctl farcasterd
[2022-12-20T07:22:02Z DEBUG farcaster_node::grpcd::runtime] GRPCD BRIDGE RPC request: Bridge Ctl farcasterd, grpcd_client<24>
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] grpcd_client<24> -> farcasterd: health_check(Bitcoin Testnet)
[2022-12-20T07:22:02Z DEBUG farcaster_node::farcasterd::runtime] launching syncer with: ["--blockchain", "Bitcoin", "--network", "Testnet", "--electrum-server", "ssl://blockstream.info:993"]
[2022-12-20T07:22:02Z DEBUG farcaster_node::farcasterd::runtime] Launching syncerd as a separate process using `/home/joel/.cargo/bin/syncerd` as binary
[2022-12-20T07:22:02Z DEBUG farcaster_node::farcasterd::runtime] tor opts: None
[2022-12-20T07:22:02Z DEBUG farcaster_node::grpcd::runtime] Received a grpc info request: Request { metadata: MetadataMap { headers: {"host": "localhost:50051", "user-agent": "Mozilla/5.0 (X11; Linux x86_64; rv:107.0) Gecko/20100101 Firefox/107.0", "accept": "application/grpc-web-text", "accept-language": "en-US,en;q=0.5", "accept-encoding": "identity,deflate,gzip", "content-type": "application/grpc", "x-user-agent": "grpc-web-javascript/0.1", "x-grpc-web": "1", "sec-fetch-site": "same-site", "origin": "http://localhost:3000", "connection": "keep-alive", "referer": "http://localhost:3000/", "sec-fetch-dest": "empty", "sec-fetch-mode": "cors", "te": "trailers"} }, message: InfoRequest { id: 0 }, extensions: Extensions }
[2022-12-20T07:22:02Z DEBUG farcaster_node::farcasterd::runtime] Executing `"/home/joel/.cargo/bin/syncerd" "-d" "~/.farcaster" "-m" "{data_dir}/msg" "-x" "{data_dir}/ctl" "-i" "{data_dir}/info" "-S" "{data_dir}/sync" "--blockchain" "Bitcoin" "--network" "Testnet" "--electrum-server" "ssl://blockstream.info:993"`
[2022-12-20T07:22:02Z DEBUG farcaster_node::grpcd::runtime] sending request over grpc bridge: Bridge(Info { request: GetInfo, service_id: Farcasterd })
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] grpcd_client<25> -> grpcd: Bridge Rpc farcasterd
[2022-12-20T07:22:02Z DEBUG farcaster_node::grpcd::runtime] GRPCD BRIDGE RPC request: Bridge Rpc farcasterd, grpcd_client<25>
[2022-12-20T07:22:02Z INFO farcaster_node::event] Syncer state transition Start -> Awaiting Syncer
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] grpcd_client<25> -> farcasterd: get_info()
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] grpcd_client<25> -> grpcd: node_info(..)
[2022-12-20T07:22:02Z ERROR microservices::esb::controller] ESB request processing error: Farcaster node errors: sending on a closed channel
[2022-12-20T07:22:02Z INFO farcaster_node::syncerd::runtime] Creating new Bitcoin (Testnet) syncer
[2022-12-20T07:22:02Z DEBUG farcaster_node::syncerd::bitcoin_syncer] bitcoin synclet using proxy: None
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] Creating ESB session for service MSG located at /home/joel/.farcaster/msg with identity 'Bitcoin (Testnet) syncer'
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] Creating ESB session for service CTL located at /home/joel/.farcaster/ctl with identity 'Bitcoin (Testnet) syncer'
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] Creating ESB session for service SYNC located at /home/joel/.farcaster/sync with identity 'Bitcoin (Testnet) syncer'
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] Creating ESB session for service INFO located at /home/joel/.farcaster/info with identity 'Bitcoin (Testnet) syncer'
[2022-12-20T07:22:02Z DEBUG microservices::esb::controller] Creating ESB session for service BRIDGE
[2022-12-20T07:22:02Z DEBUG farcaster_node::syncerd::bitcoin_syncer] creating ElectrumRpc client
[2022-12-20T07:22:02Z DEBUG farcaster_node::syncerd::bitcoin_syncer] creating ElectrumRpc client
[2022-12-20T07:22:03Z DEBUG farcaster_node::syncerd::bitcoin_syncer] New ElectrumRpc at height 2411975
[2022-12-20T07:22:03Z INFO farcaster_node::syncerd::syncer_state] Bitcoin | Incremented height 2411975
[2022-12-20T07:22:03Z DEBUG farcaster_node::syncerd::bitcoin_syncer] New ElectrumRpc at height 2411975
[2022-12-20T07:22:03Z DEBUG farcaster_node::syncerd::bitcoin_syncer] creating ElectrumRpc client
[2022-12-20T07:22:03Z DEBUG farcaster_node::syncerd::bitcoin_syncer] creating fee polling electrum client
[2022-12-20T07:22:03Z DEBUG farcaster_node::grpcd::runtime] Received a grpc info request: Request { metadata: MetadataMap { headers: {"host": "localhost:50051", "user-agent": "Mozilla/5.0 (X11; Linux x86_64; rv:107.0) Gecko/20100101 Firefox/107.0", "accept": "application/grpc-web-text", "accept-language": "en-US,en;q=0.5", "accept-encoding": "identity,deflate,gzip", "content-type": "application/grpc", "x-user-agent": "grpc-web-javascript/0.1", "x-grpc-web": "1", "sec-fetch-site": "same-site", "origin": "http://localhost:3000", "connection": "keep-alive", "referer": "http://localhost:3000/", "sec-fetch-dest": "empty", "sec-fetch-mode": "cors", "te": "trailers"} }, message: InfoRequest { id: 0 }, extensions: Extensions }
[2022-12-20T07:22:03Z DEBUG farcaster_node::grpcd::runtime] sending request over grpc bridge: Bridge(Info { request: GetInfo, service_id: Farcasterd })
[2022-12-20T07:22:03Z DEBUG microservices::esb::controller] grpcd_client<26> -> grpcd: Bridge Rpc farcasterd
[2022-12-20T07:22:03Z DEBUG farcaster_node::grpcd::runtime] GRPCD BRIDGE RPC request: Bridge Rpc farcasterd, grpcd_client<26>
[2022-12-20T07:22:03Z DEBUG microservices::esb::controller] grpcd_client<26> -> farcasterd: get_info()
[2022-12-20T07:22:03Z DEBUG microservices::esb::controller] grpcd_client<26> -> grpcd: node_info(..)
[2022-12-20T07:22:03Z ERROR microservices::esb::controller] ESB request processing error: Farcaster node errors: sending on a closed channel
[2022-12-20T07:22:03Z DEBUG farcaster_node::service] New service Bitcoin (Testnet) syncer with PID 68498 started
[2022-12-20T07:22:03Z DEBUG microservices::esb::controller] Bitcoin (Testnet) syncer -> farcasterd: hello()
[2022-12-20T07:22:03Z INFO farcaster_node::farcasterd::runtime] Service Bitcoin (Testnet) syncer is now connected
[2022-12-20T07:22:03Z INFO farcaster_node::farcasterd::runtime] Syncer Bitcoin (Testnet) syncer is registered; total 1 syncers are known
[2022-12-20T07:22:03Z INFO farcaster_node::event] Syncer state transition Awaiting Syncer -> Awaiting Syncer Request
[2022-12-20T07:22:03Z DEBUG microservices::esb::controller] farcasterd -> Bitcoin (Testnet) syncer: syncer_task(HealthCheck(HealthCheck { id: TaskId(3) }))
[2022-12-20T07:22:03Z DEBUG farcaster_node::syncerd::bitcoin_syncer] New ElectrumRpc at height 2411975
[2022-12-20T07:22:03Z DEBUG farcaster_node::syncerd::bitcoin_syncer] performing health check
[2022-12-20T07:22:03Z DEBUG farcaster_node::syncerd::bitcoin_syncer] creating ElectrumRpc client
[2022-12-20T07:22:03Z DEBUG farcaster_node::syncerd::bitcoin_syncer] New ElectrumRpc at height 2411975
[2022-12-20T07:22:03Z DEBUG microservices::esb::controller] Bitcoin (Testnet) syncer -> Bitcoin (Testnet) syncer: syncer_bridge_ev(farcasterd, HealthResult(HealthResult { id: TaskId(3), health: Healthy }))
[2022-12-20T07:22:03Z DEBUG farcaster_node::syncerd::runtime] Syncerd BRIDGE RPC request: syncer_bridge_ev(farcasterd, HealthResult(HealthResult { id: TaskId(3), health: Healthy }))
[2022-12-20T07:22:03Z DEBUG microservices::esb::controller] Bitcoin (Testnet) syncer -> farcasterd: syncer_event(HealthResult(HealthResult { id: TaskId(3), health: Healthy }))
[2022-12-20T07:22:03Z INFO farcaster_node::farcasterd::runtime] Terminating Bitcoin (Testnet) syncer
[2022-12-20T07:22:03Z INFO farcaster_node::event] Syncer state machine ended Awaiting Syncer Request -> End
[2022-12-20T07:22:03Z DEBUG microservices::esb::controller] grpcd_client<24> -> grpcd: health_result(Healthy)
[2022-12-20T07:22:03Z ERROR microservices::esb::controller] ESB request processing error: Farcaster node errors: sending on a closed channel
[2022-12-20T07:22:03Z DEBUG microservices::esb::controller] farcasterd -> Bitcoin (Testnet) syncer: terminate()
[2022-12-20T07:22:03Z INFO farcaster_node::syncerd::runtime] Received terminate on Bitcoin (Testnet) syncer
[2022-12-20T07:22:04Z DEBUG farcaster_node::grpcd::runtime] Received a grpc info request: Request { metadata: MetadataMap { headers: {"host": "localhost:50051", "user-agent": "Mozilla/5.0 (X11; Linux x86_64; rv:107.0) Gecko/20100101 Firefox/107.0", "accept": "application/grpc-web-text", "accept-language": "en-US,en;q=0.5", "accept-encoding": "identity,deflate,gzip", "content-type": "application/grpc", "x-user-agent": "grpc-web-javascript/0.1", "x-grpc-web": "1", "sec-fetch-site": "same-site", "origin": "http://localhost:3000", "connection": "keep-alive", "referer": "http://localhost:3000/", "sec-fetch-dest": "empty", "sec-fetch-mode": "cors", "te": "trailers"} }, message: InfoRequest { id: 0 }, extensions: Extensions }
[2022-12-20T07:22:04Z DEBUG farcaster_node::grpcd::runtime] sending request over grpc bridge: Bridge(Info { request: GetInfo, service_id: Farcasterd })
[2022-12-20T07:22:04Z DEBUG microservices::esb::controller] grpcd_client<27> -> grpcd: Bridge Rpc farcasterd
[2022-12-20T07:22:04Z DEBUG farcaster_node::grpcd::runtime] GRPCD BRIDGE RPC request: Bridge Rpc farcasterd, grpcd_client<27>
[2022-12-20T07:22:04Z DEBUG microservices::esb::controller] grpcd_client<27> -> farcasterd: get_info()
[2022-12-20T07:22:04Z DEBUG microservices::esb::controller] grpcd_client<27> -> grpcd: node_info(..)
[2022-12-20T07:22:04Z ERROR microservices::esb::controller] ESB request processing error: Farcaster node errors: sending on a closed channel
[2022-12-20T07:22:05Z DEBUG farcaster_node::grpcd::runtime] Received a grpc info request: Request { metadata: MetadataMap { headers: {"host": "localhost:50051", "user-agent": "Mozilla/5.0 (X11; Linux x86_64; rv:107.0) Gecko/20100101 Firefox/107.0", "accept": "application/grpc-web-text", "accept-language": "en-US,en;q=0.5", "accept-encoding": "identity,deflate,gzip", "content-type": "application/grpc", "x-user-agent": "grpc-web-javascript/0.1", "x-grpc-web": "1", "sec-fetch-site": "same-site", "origin": "http://localhost:3000", "connection": "keep-alive", "referer": "http://localhost:3000/", "sec-fetch-dest": "empty", "sec-fetch-mode": "cors", "te": "trailers"} }, message: InfoRequest { id: 0 }, extensions: Extensions }
[2022-12-20T07:22:05Z DEBUG farcaster_node::grpcd::runtime] sending request over grpc bridge: Bridge(Info { request: GetInfo, service_id: Farcasterd })
[2022-12-20T07:22:05Z DEBUG microservices::esb::controller] grpcd_client<28> -> grpcd: Bridge Rpc farcasterd
[2022-12-20T07:22:05Z DEBUG farcaster_node::grpcd::runtime] GRPCD BRIDGE RPC request: Bridge Rpc farcasterd, grpcd_client<28>
[2022-12-20T07:22:05Z DEBUG microservices::esb::controller] grpcd_client<28> -> farcasterd: get_info()
[2022-12-20T07:22:05Z DEBUG microservices::esb::controller] grpcd_client<28> -> grpcd: node_info(..)
[2022-12-20T07:22:05Z ERROR microservices::esb::controller] ESB request processing error: Farcaster node errors: sending on a closed channel
[2022-12-20T07:22:06Z DEBUG farcaster_node::grpcd::runtime] Received a grpc info request: Request { metadata: MetadataMap { headers: {"host": "localhost:50051", "user-agent": "Mozilla/5.0 (X11; Linux x86_64; rv:107.0) Gecko/20100101 Firefox/107.0", "accept": "application/grpc-web-text", "accept-language": "en-US,en;q=0.5", "accept-encoding": "identity,deflate,gzip", "content-type": "application/grpc", "x-user-agent": "grpc-web-javascript/0.1", "x-grpc-web": "1", "sec-fetch-site": "same-site", "origin": "http://localhost:3000", "connection": "keep-alive", "referer": "http://localhost:3000/", "sec-fetch-dest": "empty", "sec-fetch-mode": "cors", "te": "trailers"} }, message: InfoRequest { id: 0 }, extensions: Extensions }
[2022-12-20T07:22:06Z DEBUG farcaster_node::grpcd::runtime] sending request over grpc bridge: Bridge(Info { request: GetInfo, service_id: Farcasterd })
[2022-12-20T07:22:06Z DEBUG microservices::esb::controller] grpcd_client<29> -> grpcd: Bridge Rpc farcasterd
[2022-12-20T07:22:06Z DEBUG farcaster_node::grpcd::runtime] GRPCD BRIDGE RPC request: Bridge Rpc farcasterd, grpcd_client<29>
[2022-12-20T07:22:06Z DEBUG microservices::esb::controller] grpcd_client<29> -> farcasterd: get_info()
[2022-12-20T07:22:06Z DEBUG microservices::esb::controller] grpcd_client<29> -> grpcd: node_info(..)
[2022-12-20T07:22:06Z ERROR microservices::esb::controller] ESB request processing error: Farcaster node errors: sending on a closed channel
So: I only see the errors when the browser refresh, either because of the npm run dev in the GUI or because of me refreshing the page. Otherwise, if a page like e.g. the node info or list do calls and the sidebar also do calls at the same time, no issues. I think this is not a concurrency issue but a connection issue, when refreshing the browser cuts the connections' pending requests and when grpcd tries to reply whe get:
[2022-12-20T07:22:06Z ERROR microservices::esb::controller] ESB request processing error: Farcaster node errors: sending on a closed channel
If we can swallow these errors and not bug the grpcd that would work.
TheCharlatan commented
Thank you so much! I think I understood what is happening and opened PR #872.