EN -> SCN 체인 간 전송 시 Pending 문의

한국어🇰🇷 클레이튼
1

긴급하게 문의 드립니다.

EN → SCN 체인간 전송 시 Pending이 발생하여 로그를 분석한 결과 아래의 사유로 인하여 발생하는 것으로 추정됩니다.

Pending에 대해서 Clear를 진행하고 싶은 데 어떻게 진행을 해야 할 지 문의 드립니다.

[추정 원인]
baobab 내 EOA간 klay 전송 시 SCN으로 변경사항이 발생한 것에 대해서 notification 하지 않으나
EOA에서 Bridge CA에 klay 전송 시 Subscription으로 인해 SCN 변경사항이 있다고 인지되어 Tx 발생.
SCN에서 해당 Tx를 처리하지 못하여 Pending 발생.

[버전]
SCN : Klaytn/v1.9.1+8664bc8831/linux-amd64/go1.15.7
EN : Klaytn/v1.9.1+8664bc8831/linux-amd64/go1.15.7

[Error Log]
13:59 이후 부터 Pending Evnet(bi.pendingRequestEvent) 1 지속 유지

TRACE[11/23,12:13:59 +09] [45] added pending request events to the bridge info:  ^[[01;31m^[[Kbi.pendingRequestEvent=1^[[m^[[K
TRACE[11/23,12:13:59 +09] [45] added pending request events to the bridge info:  ^[[01;31m^[[Kbi.pendingRequestEvent=1^[[m^[[K
TRACE[11/23,12:13:59 +09] [45] added pending request events to the bridge info:  ^[[01;31m^[[Kbi.pendingRequestEvent=1^[[m^[[K
TRACE[11/23,12:14:00 +09] [45] added pending request events to the bridge info:  ^[[01;31m^[[Kbi.pendingRequestEvent=1^[[m^[[K
TRACE[11/23,12:14:00 +09] [45] added pending request events to the bridge info:  ^[[01;31m^[[Kbi.pendingRequestEvent=1^[[m^[[K
TRACE[11/23,12:14:00 +09] [45] added pending request events to the bridge info:  ^[[01;31m^[[Kbi.pendingRequestEvent=1^[[m^[[K
TRACE[11/23,12:14:01 +09] [45] added pending request events to the bridge info:  ^[[01;31m^[[Kbi.pendingRequestEvent=1^[[m^[[K
TRACE[11/23,12:14:02 +09] [45] added pending request events to the bridge info:  ^[[01;31m^[[Kbi.pendingRequestEvent=1^[[m^[[K
TRACE[11/23,12:14:03 +09] [45] added pending request events to the bridge info:  ^[[01;31m^[[Kbi.pendingRequestEvent=1^[[m^[[K
TRACE[11/23,12:14:04 +09] [45] added pending request events to the bridge info:  ^[[01;31m^[[Kbi.pendingRequestEvent=1^[[m^[[K
=========================================================
INFO[^[[01;31m^[[K11/23,12^[[m^[[K:13:59 +09] [45] ^[[01;31m^[[KVT^[[m^[[K : Parent -> Child Chain                request=17 handle=17 lowerHandle=17 pending=0
INFO[^[[01;31m^[[K11/23,12^[[m^[[K:13:59 +09] [45] ^[[01;31m^[[KVT^[[m^[[K : Child -> Parent Chain                request=22 handle=22 lowerHandle=22 pending=0
INFO[^[[01;31m^[[K11/23,12^[[m^[[K:14:00 +09] [45] ^[[01;31m^[[KVT^[[m^[[K : Parent -> Child Chain                request=18 handle=17 lowerHandle=17 pending=1
INFO[^[[01;31m^[[K11/23,12^[[m^[[K:14:00 +09] [45] ^[[01;31m^[[KVT^[[m^[[K : Child -> Parent Chain                request=22 handle=22 lowerHandle=22 pending=0
INFO[^[[01;31m^[[K11/23,12^[[m^[[K:14:01 +09] [45] ^[[01;31m^[[KVT^[[m^[[K : Parent -> Child Chain                request=18 handle=17 lowerHandle=17 pending=1
INFO[^[[01;31m^[[K11/23,12^[[m^[[K:14:01 +09] [45] ^[[01;31m^[[KVT^[[m^[[K : Child -> Parent Chain                request=22 handle=22 lowerHandle=22 pending=0

EOA에서 Bridge CA로 klay 전송 시 SCN에서 변경사항을 인지하여 Tx 생성하여 처리를 수행하려 하였으나
nonce too low 사유로 Discarding 처리됨.

TRACE[11/23,12:13:59 +09] [39] rpc client Notification                   msg="<-readResp: notification {\"jsonrpc\":\"2.0\",\"method\":\"klay_subscription\",\"params\":{\"subscription\":\"0xd386042358498274b770ca12ebeb6d64\",\"result\":{\"address\":\"0x73e3f40ed2d2dbb34ae1f7ee56359c153c5e09fe\",\"topics\":[\"0xeff76c36e53fa5ff52f27acc8a34d5047a8246abb07b77b12f1309f71e337f09\",\"0x000000000000000000000000839f90ce9f3e10c08368605e58da04016eff2be1\",\"0x000000000000000000000000839f90ce9f3e10c08368605e58da04016eff2be1\",\"0x0000000000000000000000000000000000000000000000000000000000000000\"],\"data\":\"0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000025f273933db57000000000000000000000000000000000000000000000000000000000000000000011000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000a00000000000000000000000000000000000000000000000000000000000000000\",\"blockNumber\":\"0x669cacc\",\"transactionHash\":\"0x37dd77066cb9d949f350b27ecbd84259caf22e08b84ece3755acb31f28ded289\",\"transactionIndex\":\"0x0\",\"blockHash\":\"0x92c298706fec4f223446b631381593a485c451f7bf6965a459876f3547ed1304\",\"logIndex\":\"0x0\",\"removed\":false}}}"
TRACE[11/23,12:13:59 +09] [45] received rpc ServiceChainResponse
TRACE[11/23,12:13:59 +09] [45] send rpc response to the rpc client
TRACE[11/23,12:13:59 +09] [45] received rpc ServiceChainResponse
TRACE[11/23,12:13:59 +09] [45] send rpc response to the rpc client
TRACE[11/23,12:13:59 +09] [45] received rpc ServiceChainResponse
TRACE[11/23,12:13:59 +09] [39] rpc client Notification                   msg="<-readResp: notification {\"jsonrpc\":\"2.0\",\"method\":\"klay_subscription\",\"params\":{\"subscription\":\"0x5e859b99e2af91da9c2aff04c10cfe9\",\"result\":{\"address\":\"0x73e3f40ed2d2dbb34ae1f7ee56359c153c5e09fe\",\"topics\":[\"0xeff76c36e53fa5ff52f27acc8a34d5047a8246abb07b77b12f1309f71e337f09\",\"0x000000000000000000000000839f90ce9f3e10c08368605e58da04016eff2be1\",\"0x000000000000000000000000839f90ce9f3e10c08368605e58da04016eff2be1\",\"0x0000000000000000000000000000000000000000000000000000000000000000\"],\"data\":\"0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000025f273933db57000000000000000000000000000000000000000000000000000000000000000000011000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000a00000000000000000000000000000000000000000000000000000000000000000\",\"blockNumber\":\"0x669cacc\",\"transactionHash\":\"0x37dd77066cb9d949f350b27ecbd84259caf22e08b84ece3755acb31f28ded289\",\"transactionIndex\":\"0x0\",\"blockHash\":\"0x92c298706fec4f223446b631381593a485c451f7bf6965a459876f3547ed1304\",\"logIndex\":\"0x0\",\"removed\":false}}}"
TRACE[11/23,12:13:59 +09] [45] send rpc response to the rpc client
TRACE[11/23,12:13:59 +09] [45] received rpc ServiceChainResponse
TRACE[11/23,12:13:59 +09] [45] send rpc response to the rpc client
TRACE[11/23,12:13:59 +09] [39] rpc client Notification                   msg="<-readResp: notification {\"jsonrpc\":\"2.0\",\"method\":\"klay_subscription\",\"params\":{\"subscription\":\"0x289a459c32921edf862a06dbc232fa4d\",\"result\":{\"address\":\"0x73e3f40ed2d2dbb34ae1f7ee56359c153c5e09fe\",\"topics\":[\"0xeff76c36e53fa5ff52f27acc8a34d5047a8246abb07b77b12f1309f71e337f09\",\"0x000000000000000000000000839f90ce9f3e10c08368605e58da04016eff2be1\",\"0x000000000000000000000000839f90ce9f3e10c08368605e58da04016eff2be1\",\"0x0000000000000000000000000000000000000000000000000000000000000000\"],\"data\":\"0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000025f273933db57000000000000000000000000000000000000000000000000000000000000000000011000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000a00000000000000000000000000000000000000000000000000000000000000000\",\"blockNumber\":\"0x669cacc\",\"transactionHash\":\"0x37dd77066cb9d949f350b27ecbd84259caf22e08b84ece3755acb31f28ded289\",\"transactionIndex\":\"0x0\",\"blockHash\":\"0x92c298706fec4f223446b631381593a485c451f7bf6965a459876f3547ed1304\",\"logIndex\":\"0x0\",\"removed\":false}}}"
TRACE[11/23,12:13:59 +09] [45] received rpc ServiceChainResponse
TRACE[11/23,12:13:59 +09] [45] send rpc response to the rpc client
TRACE[11/23,12:13:59 +09] [45] received rpc ServiceChainResponse
TRACE[11/23,12:13:59 +09] [45] send rpc response to the rpc client
TRACE[11/23,12:13:59 +09] [39] rpc client Notification                   msg="<-readResp: notification {\"jsonrpc\":\"2.0\",\"method\":\"klay_subscription\",\"params\":{\"subscription\":\"0x7247a8f4edcd2ed148b5631c2f3d7fd4\",\"result\":{\"address\":\"0x73e3f40ed2d2dbb34ae1f7ee56359c153c5e09fe\",\"topics\":[\"0xeff76c36e53fa5ff52f27acc8a34d5047a8246abb07b77b12f1309f71e337f09\",\"0x000000000000000000000000839f90ce9f3e10c08368605e58da04016eff2be1\",\"0x000000000000000000000000839f90ce9f3e10c08368605e58da04016eff2be1\",\"0x0000000000000000000000000000000000000000000000000000000000000000\"],\"data\":\"0x0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000025f273933db57000000000000000000000000000000000000000000000000000000000000000000011000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000a00000000000000000000000000000000000000000000000000000000000000000\",\"blockNumber\":\"0x669cacc\",\"transactionHash\":\"0x37dd77066cb9d949f350b27ecbd84259caf22e08b84ece3755acb31f28ded289\",\"transactionIndex\":\"0x0\",\"blockHash\":\"0x92c298706fec4f223446b631381593a485c451f7bf6965a459876f3547ed1304\",\"logIndex\":\"0x0\",\"removed\":false}}}"
TRACE[11/23,12:13:59 +09] [45] added pending request events to the bridge info:  bi.pendingRequestEvent=1
TRACE[11/23,12:13:59 +09] [45] Get ready request value transfer event    len(readyEvent)=1 len(pendingEvent)=0
TRACE[11/23,12:13:59 +09] [5] Discarding invalid transaction            hash=43d4bd▒~@▒77a9b0                                                      err="nonce too low"
2

안녕하세요, 브릿지 노드의 data 디렉토리에 bridge_transactions.rlp 파일을 확인하실수 있으실텐데 노드를 종료후에 bridge_transactions.rlp 파일을 지운 후 다시한번 테스트 부탁드립니다.

1개의 좋아요
3

main-bridge는 해당 파일이 없는 것으로 알고 있습니다.
sub-bridge 말씀을 하시는 거라면,
SCN 에서 bridge_transactions.rlp를 삭제한 이후 kscnd 프로세스를 재 기동을 수행하였고
현상은 동일하게 pending이 해소 되고 있지 않습니다.

4

pending이 다시 내려가진 않지만 로그는 멈추지 않았나요? 혹시 원하시는바가 pending을 0으로 맞추고싶으신건가요? 그렇다면 다음의 문서를 참고부탁드립니다 (Value Transfer - Klaytn Docs). Recovery 기능은 실패한 트랜잭션에 대해서 다시 트랜잭션을 생성하여(새 논스값으로) 트랜잭션을 다시보냅니다.

5

빠른 답변 감사합니다. ^^

추가적으로 문의 드립니다.

  1. EOA에서 Bridge CA로 klay 전송 시 문제가 발생한 것으로 추정된다고 말씀 드렸는데,
    handleNonce, lowerHandleNonce, requestNonce를 강제로 설정(or 초기화)할 수 있는 방법이 있는 지 문의 드립니다.

  2. 상기 방법이 없다면, 원인이 되는 Tx를 제거 or 취소를 하고 싶은데 어떻게 해야 하는 지 문의 드립니다.
    SCN에서 확인 시 pending Tx가 없다고 나옵니다.

> subbridge.txPendingCount
0
> subbridge.txPending
{}
  1. 추가로 원인 분석 확인에 필요한 사항이 있으면 회신 요청 드립니다.

회신 주신 사항에 대해서는 아래 답변 드립니다.

pending이 다시 내려가진 않지만 로그는 멈추지 않았나요?
==> 로그가 멈춘다는 의미가 "pending =1이 더 이상 발생하지 않느냐? "라는 인가요? Tx 발생 시 pending=1 이 pending=2로 증가 합니다.
pending이 발생한 이후 Tx는 처리되지 않고 pending 처리되고 있어 handleNonce와 lowerHandleNonce 의 gap이 증가하고 있습니다.

혹시 원하시는바가 pending을 0으로 맞추고싶으신건가요? 그렇다면 다음의 문서를 참고부탁드립니다 (Value Transfer - Klaytn Docs ). Recovery 기능은 실패한 트랜잭션에 대해서 다시 트랜잭션을 생성하여(새 논스값으로) 트랜잭션을 다시보냅니다.
==>
정상적으로 체인간 전송을 복구하기 위하여 원인을 분석 한 결과 상기 기재한 것이 원인으로 의심되어
해당 Tx를 제거하고자 문의를 드렸습니다.

그리고, Recovery 기능은 on 상태로 운용 중이였습니다.

> subbridge.getBridgeInformation("0x73e3f40ed2d2dbb34ae1f7ee56359c153c5e09fe")
{
  counterPart: "0x59c6989aee4398e841be52cc14a56ddca3995644",
  handleNonce: 23,
  isRunning: true,
  isSubscribed: true,
  lowerHandleNonce: 23,
  onServiceChain: false,
  pendingEventSize: 0,
  requestNonce: 23
}
> subbridge.getBridgeInformation("0x59c6989aee4398e841be52cc14a56ddca3995644")
{
  counterPart: "0x73e3f40ed2d2dbb34ae1f7ee56359c153c5e09fe",
  handleNonce: 24,
  isRunning: true,
  isSubscribed: true,
  lowerHandleNonce: 17,
  onServiceChain: true,
  pendingEventSize: 0,
  requestNonce: 24
}
6
  1. 해당 변수들은 컨트랙트에서 읽어오는 값이라서 컨트랙트 콜 없이 강제로 변경은 불가능합니다
  2. 노드를 종료한 뒤 bridge_transactions 파일을 지우고 다시 노드를 실행하면 초기 브릿지 트랜잭션 풀이 초기화되기때문에 이전 풀에 있던 트랜잭션은 다시 실행되지 않습니다. (트랜잭션 풀에 트랜잭션이 없으므로 해당 API로 출력되지 않은것으로 보입니다) 그래서 added pending request events to the bridge info 해당 로그가 더이상 출력되지않냐는 뜻이었습니다. pending= 은 해당 실패한 트랜잭션을 가진 넌스가 다시 실행에 성공되지않는 이상 0이 되지않습니다. pending은 실제로 실패한 트랜잭션의 갯수를 표현하는게아니라 requestNonce - lowerHandleNonce 로 표현되기때문에 이후에 성공에 실행한 트랜잭션 갯수가 더 많아질수록 pending 숫자가 더 증가하게됩니다. (로그의 시멘틱이 잘못되어있어서 다른기능을 개발하면서 고치려고 했으나 ([SC] Value transfer rollback by hyunsooda · Pull Request #1565 · klaytn/klaytn · GitHub) 현재는 더 이상 개발이 이루어지지 않고있습니다.
  3. subbridge.getBridgeInformation 함수로는 recovery 옵션의 활성화상태를 알 수 없는데 혹시 어떤의미이신가요? recovery 기능은 실패한 트랜잭션을 찾아서 다시 재생성하여 실행시킴으로써 status를 올바르게 맞출 수있습니다. recovery기능이 실행되고있던게 맞다면 해당 관련로그 첨부 부탁드립니다. 더불어, 왜 SCN에서 tx가 실패했는지 트랝개션 디버깅로그(debug_traceTransaction)도 한번 찾아봐주시기 바랍니다.
7

답변 감사합니다.

recovery 기능이 실행되고 있다고 말씀 드린 이유는 config 상에서 설정이 되어 운용되는 상태였기 때문에 기능이 on되어 있다고

SC_VTRECOVERY=1 # value transfer recovery activation
SC_VTRECOVERY_INTERVAL=5 # recovery interval

말씀하신 로그는  이걸로 추정됩니다.
TRACE[11/23,21:30:10 +09] [45] recover pending events
TRACE[11/23,21:30:10 +09] [45] recovery prevHint                         rnonce=24 hnonce=24 phnonce=24 cand=true
TRACE[11/23,21:30:10 +09] [45] recovery prevHint                         rnonce=30 hnonce=17 phnonce=17 cand=false
TRACE[11/23,21:30:10 +09] [45] recover pending events
TRACE[11/23,21:30:14 +09] [45] recovery prevHint                         rnonce=24 hnonce=24 phnonce=24 cand=true
TRACE[11/23,21:30:14 +09] [45] recovery prevHint                         rnonce=30 hnonce=17 phnonce=17 cand=true

무슨 이유인지는 정확히 알 수 없지만
상기 파라미터를 0으로 변경했다 재기동, 다시 1로 변경하고 재기동한 이후(bridge_transactions.rlp 삭제 포함) added pending request events to the bridge info: bi.pendingRequestEvent=0으로 출력되고 있으며
현재 정상적으로 Tx를 처리하고 있습니다.
또한, 말씀하신대로 pending count는 Tx 만큼 증가하고 있습니다.

8

다만, 리커버리 옵션을 켠 상태라면 실패했던 넌스의 트랜잭션을 찾아서 다시실행시키기때문에 pending=0이 될 수 있습니다. 리커버리 옵션을 켰는데도 여전히 pending이 올라가고있는 상태인가요? 맞다면 17번 넌스의 트랜잭션이 애초에 실행될 수 없는 트랜잭션일수도 있을 것 같습니다 (현재 브릿지컨트랙트가 소유하고있는 클레이보다 더 높은 클레이로 요청했거나 등등). 17번넌스의 트랜잭션 해시를 debug_traceTransaction으로 어떻게 처리가안되었나 확인부탁드립니다.

2개의 좋아요