search

ergo-services / ergo

An actor-based Framework with network transparency for creating event-driven architecture in Golang. Inspired by Erlang. Zero dependencies.
https://docs.ergo.services
MIT License
3.51k stars 138 forks source link

RPC call sometimes returns the error 'timeout' instantly #45

Closed Noksa closed 3 years ago

Noksa commented 3 years ago

Hello again :)

I've found an unexpected behavior when I run RPC Calls from golang to an erlang node.

Please help me to understand why it happens. Thanks.

You can find the log from go below. As you may see sometimes for some RPC call command the timeout error is returned instantly after calling RPC for no reason (I have 8 seconds timeout)

INFO[0018] Erlang collector started fetching metrics    
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
ERRO[0018] Error: timeout, Result: <nil>                
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe1, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe1, 0x59e9, 0x0}}, etf.Tuple{247329, 4241}}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe2, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe2, 0x59e9, 0x0}}, etf.Tuple{247487, 158}}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe3, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe3, 0x59e9, 0x0}}, etf.Tuple{247645, 158}}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe4, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe4, 0x59e9, 0x0}}, etf.Tuple{247803, 158}}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe5, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe5, 0x59e9, 0x0}}, etf.Tuple{247961, 158}}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe6, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe6, 0x59e9, 0x0}}, etf.Tuple{2365, 0}}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
ERRO[0018] Error: timeout, Result: <nil>                
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe7, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe7, 0x59e9, 0x0}}, etf.Tuple{2368, 0}}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe8, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe8, 0x59e9, 0x0}}, etf.Tuple{2371, 0}}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe9, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fe9, 0x59e9, 0x0}}, etf.Tuple{2374, 0}}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fea, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fea, 0x59e9, 0x0}}, etf.Tuple{2377, 0}}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5feb, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5feb, 0x59e9, 0x0}}, 1}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fec, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fec, 0x59e9, 0x0}}, 1}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fed, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fed, 0x59e9, 0x0}}, 1}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fee, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fee, 0x59e9, 0x0}}, 1}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fef, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5fef, 0x59e9, 0x0}}, 1}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff0, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff0, 0x59e9, 0x0}}, 1}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff1, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff1, 0x59e9, 0x0}}, 1}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff2, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff2, 0x59e9, 0x0}}, 1}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff3, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff3, 0x59e9, 0x0}}, 1}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff4, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff4, 0x59e9, 0x0}}, 1}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff5, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff5, 0x59e9, 0x0}}, 0}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff6, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff6, 0x59e9, 0x0}}, 0}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff7, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff7, 0x59e9, 0x0}}, 0}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff8, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff8, 0x59e9, 0x0}}, 0}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff9, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ff9, 0x59e9, 0x0}}, 0}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ffa, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ffa, 0x59e9, 0x0}}, 0}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ffb, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ffb, 0x59e9, 0x0}}, 0}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ffc, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ffc, 0x59e9, 0x0}}, 0}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ffd, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ffd, 0x59e9, 0x0}}, 0}
2021/04/29 19:59:35 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/04/29 19:59:35 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3ef, Serial:0x1, Creation:0x1}}
2021/04/29 19:59:35 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1007 1 1}
2021/04/29 19:59:35 [test@MBP-Alexandr]. {test@MBP-Alexandr 1007 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/04/29 19:59:35 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ffe, 0x59e9, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x5ffe, 0x59e9, 0x0}}, 0}
INFO[0018] Erlang collector fetched metrics

I've created a func to retry failed calls but it's just a workaround:

func (rpc RPC) runCommand(node string, module string, f string, args ...etf.Term) etf.Term {
    var res etf.Term
    var err error
    for i := 0; i < 5; i++ {
        if args == nil {
            res, err = rpc.process.CallRPCWithTimeout(8, node, module, f)
        } else {
            if len(args) == 1 {
                res, err = rpc.process.CallRPCWithTimeout(8, node, module, f, args[0])
            } else {
                res, err = rpc.process.CallRPCWithTimeout(8, node, module, f, args)
            }
        }
        if err != nil {
            log.Errorf("Error: %v, Result: %v\n", err, res)
            continue
        }
    }
    return res
}
halturin commented 3 years ago

I will take a look later. But before, here is a little tip for your golang code. CallRPCWithTimeout - variadic function and you don't need to use these if/else statements. Just unfold args...

     rpc.process.CallRPCWithTimeout(8, node, module, f, args...)

so your code should be like 

for i := 0; i < 5; i++ {
    res, err = rpc.process.CallRPCWithTimeout(8, node, module, f, args...) 
    // handle res and err variables
}
halturin commented 3 years ago

May I ask you to provide more detail on how to reproduce this behavior? And what version of Golang do you use? I'm asking about versions because there were few problems with the Golang Timer under the hood (in 1.4.0 and 1.4.1, in 1.6.0 AFAIK had another problem with the timer).

Noksa commented 3 years ago

Sure! I’ll provide an example in a few days, I’m just on holidays now.

Noksa commented 3 years ago

You can try to reproduce this error as follows (I tried it on Mac): 1) Install erlang@22 via homebrew (brew install erlang@22) 2) Run an erlang node using the following command (just change YOUR_HOST_NAME placeholder):

➜ ~ /usr/local/opt/erlang@22/bin/erl -sname demo@YOUR_HOST_NAME -setcookie 123

3) Checkout a code from here: https://github.com/Noksa/erlang-test 4) Build it via go build 5) Run it using the following flags (just change YOUR_HOST_NAME placeholder):

./erlang-test -name test@YOUR_HOST_NAME -target demo@YOUR_HOST_NAME -trace.dist -trace.node

6) Wait a bit or run it again and eventually you will receive the error. I receive this error after 20-30 seconds:

2021/05/10 15:24:37 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/05/10 15:24:37 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/05/10 15:24:37 Node control: etf.Tuple{2, "", etf.Pid{Node:"test@MBP-Alexandr", ID:0x3eb, Serial:0x1, Creation:0x1}}
2021/05/10 15:24:37 [test@MBP-Alexandr] sending message by pid {test@MBP-Alexandr 1003 1 1}
2021/05/10 15:24:37 [test@MBP-Alexandr]. {test@MBP-Alexandr 1003 1 1} got message from etf.Pid{Node:"", ID:0x0, Serial:0x0, Creation:0x0}
2021/05/10 15:24:37 got reply: etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x60f9, 0x59f6, 0x0}}
etf.Tuple{etf.Ref{Node:"test@MBP-Alexandr", Creation:0x1, ID:[]uint32{0x60f9, 0x59f6, 0x0}}, etf.Tuple{5888085, 158}}
2021/05/10 15:24:37 Result: [5888085 158]
2021/05/10 15:24:37 [test@MBP-Alexandr] RPC calling: demo@MBP-Alexandr:erlang:statistics
2021/05/10 15:24:37 [test@MBP-Alexandr] sending message by tuple [rex demo@MBP-Alexandr]
2021/05/10 15:24:37 Error: timeout, Result: <nil>
halturin commented 3 years ago

thanks a lot for the details. what is the golang version?

Noksa commented 3 years ago

1.16

halturin commented 3 years ago

I meant what exact version :). Please, show the output of

go version

Noksa commented 3 years ago

@halturin Oh sorry, I misunderstood you :) 

➜ ~ go version
go version go1.16.2 darwin/amd64
halturin commented 3 years ago

Thanks for the patience. Its really nice catch. Just merged a fix and made a new release tag. here is PR https://github.com/halturin/ergo/pull/48

Noksa commented 3 years ago

@halturin Awesome!