Caver-js 를 이용하여 RPC Node 접속시 부하 증가 문제

[kyle.kwon]

안녕하세요.
SCN 1.8.4 로 서비스체인을 구성하였습니다.
그리고 nodejs + express + caver-js 로 SCN RPC node 와 통신하는 API 서버를 개발하였습니다.

저희 API 서버와 SCN RPC node 간의 트래픽이 증가 하면 어느 순간부터,
tcp connection(http) 이 계속 증가합니다. 이는 keepAlive 옵션이 기본으로 true 로 되기 때문인듯 합니다.
그런데 문제는 timeout 옵션을 주어도 변화가 없습니다.

const httpProv = new Caver.providers.HttpProvider(nodeURL,{timeout: 2000});
super(httpProv, httpOption)

여기 까지는 괜찮은데 문제는,
TCP connection 이 증가 하면서 동시에 API 서버, SCN Node 모두 부하가 증가 합니다.
SCN 쪽에 log 옵션을 5로 주고 로그를 확인해보았더니,
아래와 같이 엄청나게 많은 klay_GetTransactionReceipt 요청이
끊임없이 계속 이루어지고 있었습니다. (never ending…)
이미 저희 API 에서는 이미 모든 작업이 끝났는데도(?) 말이죠…

테스트로 저희 API 서버쪽에서 SCN RPC node 로 1000 개의 tx를 초당 10개씩 보내보았습니다.
그랬더니 transction receipt 를 못 받는게 몇개씩 생기더라구요…
이런게 누적이 되어서 몇일 지나면 서비스 중지 사태까지 발생합니다.

이 문제를 해결할 수 있는 방법이 있을까요?
참고로 caver-js 1.9.0, SCN 1.9 에서도 동일한 증상이 발생합니다.
그래서 지금 1주일 마다 API 서버를 재시작 하고 있습니다.ㅠ ㅠ
꼭 답변 부탁 드립니다.

RACE[09/20,02:03:05 Z] [39] Request info                              reqId=&14162549 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&14162557 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&14162560 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&14162558 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&14162564 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493005 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493006 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493012 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493015 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493019 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493024 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493031 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493029 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493036 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493039 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493045 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493049 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493054 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&10493056 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
INFO[09/20,02:03:05 Z] [50] Commit new mining work                    number=2910002 hash=5c5ca6…92d62c                                                      txs=0  elapsed=304.36µs    commitTime=189.443µs finalizeTime=91.037µs
INFO[09/20,02:03:05 Z] [25] received more than 2f agreements and change state to prepared  msgType=1 prepareMsgNum=3 commitMsgNum=0
INFO[09/20,02:03:05 Z] [24] Committed                                 number=2910002 hash=22433a…76b348                                                      address=0xb9B95b00EC5DCbD74cAEF7ECbF513e278f62f2E9
INFO[09/20,02:03:05 Z] [50] Successfully sealed new block             number=2910002 hash=22433a…76b348
INFO[09/20,02:03:05 Z] [50] Successfully wrote mined block            num=2910002 hash=22433a…76b348                                                      txs=0  elapsed=444.876µs
INFO[09/20,02:03:05 Z] [50] Mining too far in the future              wait=1s
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&13692544 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&13692549 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&12077297 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&13692556 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&12077298 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt
TRACE[09/20,02:03:05 Z] [39] Request info                              reqId=&12077300 reqErr=nil isUnsubscribe=false reqMethod=klay_GetTransactionReceipt 

[sungmean_k]

서버투 블록체인 노드 환경이면 컨넥션을 재활용하시는게 나아 보입니다.

[jack_jin]

안녕하세요, 초당 10개정도의 요청은 노드에 전혀 무리없는 수준이라고 생각되는데요,

요청에 응답하지 못하는 다른 문제가 있을거라 생각됩니다. 먼저 요청수를 초당 1~2개정도로 낮춰도 동일한 문제가

발생하는지와 SCN노드 스펙 공유 부탁드립니다.

[kyle.kwon]

SCN version : 1.9
SCN node : AWS t2.xlarge (vCPU: 4, RAM 16G, SSD: 5T), 노드 4대 구성.

저의 예상으로는…
문제의 상황에서 caver-js 에 소스에 breakpoint 를 몇군데 걸고 봤더니,
caver-js 에서 끊임없이 klay_getTransactionReceipt 를 요청합니다.
그런데 이때 txhash 는 실패한 tx 라서… 아무리 receipt 를 요청해도 돌아 오는 응답은 null 입니다.

API 서버에서 요청하는 tx 중 nonce 중복 에러(there is already same nonce…) 가 발생하는건이 꽤 있는데,
이 에러가 발생한 tx 중 일부 (모두는 아닙니다) 에 대하여,
어떤 이유에서인지 모르게 클라이언트(API Server 의 caver-js) 가 에러 자체를 리턴받지 못해,
그 이후 부터 caver-js 가 해당 tx 에 대하여 klay_getTransactionReceipt 요청을
무한 반복하게 되는 상황으로 빠지는게 되는게 원인이 아닌가 싶습니다.

의도적으로 tx 중 nonce 중복 에러(there is already same nonce…) 가 많이 발생하도록 하여 tx 를 발생시켜 보면,
에러 재현이 가능할 듯 하오니 참고 부탁 드립니다.
nonce 값을 직접 채우지 않고 fillTransaction 으로 nonce 가 채워지도록하고,
동일한 주소로 초당 10 개 이상의 tx 를 발생시키게 되면 아마도 꽤 많은 tx 가 nonce 에러로 실패하게 될겁니다.
실패하는 것은 정상이나, 실패에 대한 처리 결과가 일부 tx 에 대하여 receipt 무한 요청으로 이어지는게 문제라 보여집니다.

[kyle.kwon]

네… 재활용 하고 있습니다.
문제는 유지 되는 tcp connection 이 재활용을 위해 free 상태로 유지되는것이 아니라…
해당 connection 으로 끊임없이 klay_getTransactionReceipt 요청이 이루어진다는 것입니다.
그것도 실패하여 존재하지 않는 txhash 값으로… 영원히 receipt 가 null 이 리턴되는 tx 에 대하여 무한 반복으로…
그리고 이런 문제의 tx 가 계속 쌓여 나중에는 어마어마한 receipt 요청이 발생하여 서비스 중지 상태까지 이어집니다.

[jack_jin]

klay_getTransactionReceipt 요청에 time 또는 count limit이 필요할 수도 있겠네요, 해당부분은 한번 확인해보겠습니다.

그런데, there is already same nonce 에러가 발생하는 이유에 대해서도 파악해보면 좋을것같습니다.
저는 초당 천 단위까지도 caver를 이용해서 트랜잭션 전송 테스트를 해보았을때 큰 문제가 발견되지는 않았습니다.

[kyle.kwon]

nonce 에러가 발생하는 것에 대해서는 인지하고 있습니다.
서비스의 클라이언트 쪽과 함께 수정되어야 하는 문제라
일단은 에러가 나면 재요청하는 방식으로 진행하고
향후 업그레이드를 고려중입니다.

서비스 단의 문제와는 별개로…
블록체인 단(caver-js + kscnd) 에서, 에러가 나면 에러로 처리가 잘 되면 괜찮은데,
무한루프로 빠지는 이런 상황이 발생하여…
어떤 조치를 취해야 할지 몰라 문의 드렸습니다.

[jack_jin]

네 조금 시간이 걸릴수 있지만, receipt관련 내용은 확인후에 공유드릴수 있도록 하겠습니다.