[fabric-rest] TIMEOUT 오류 발생 및 해결 방안

fabric-rest TIMEOUT 오류 발생 및 해결 방안

현상 조사

현상

honeybee_1.2 네트워크에서 fabric-rest API에 데이터를 POST 할 경우, "REQUEST_TIMEOUT" 오류가 발생함

아래 과정까지는 수행되고 실제 트랜잭션이 생성되는 것도 확인. (다른 org에서 해당 데이터 query 가능)

• Sending transaction proposal

• transaction proposal was good

• Successfully sent Proposal and received ProposalResponse

• Committing transaction

아래 과정이 수행되지 않음

• Got block event

• Invoke succeed

• event promise all complete and testing complete

• Successfully sent transaction to the orderer

Orderer 컨테이너로 트랜잭션이 제대로 broadcast 되지 않아 발생하는 오류로 추정됨.

fabric-rest API 컨테이너를 다시 시작하면(restart) 처음엔 정상적으로 동작하다가 시간이 지나면 다시 동일 오류가 발생함.

honeybee_server, honeybee_cloud에서도 동일 오류 발생 -> 클라우드 환경 문제로 추정됨

fabric-rest API 컨테이너 오류 로그 (hyperledger-new-003 기준 로그)

[2018-11-22 07:43:26.765] [DEBUG] API - POST  /channels/honeybeechannel/chaincodes/tracecc
[2018-11-22 07:43:26.767] [DEBUG] WebApp - Decoded from JWT token: username - postman, orgname - org3
[2018-11-22 07:43:26.767] [DEBUG] WebApp - ==================== INVOKE ON CHAINCODE ==================
[2018-11-22 07:43:26.767] [DEBUG] WebApp - channelName  : honeybeechannel
[2018-11-22 07:43:26.767] [DEBUG] WebApp - chaincodeName : tracecc
[2018-11-22 07:43:26.767] [DEBUG] WebApp - peersId  :  ["org3/peer0"]
[2018-11-22 07:43:26.767] [DEBUG] WebApp - peers  :  ["<서버의 IP주소>:7051"]
[2018-11-22 07:43:26.767] [DEBUG] WebApp - fcn  : registerFarm
[2018-11-22 07:43:26.768] [DEBUG] WebApp - args  : 농장번호,농장식별번호,소유주,주소,전화번호
[2018-11-22 07:43:26.768] [DEBUG] invoke-chaincode -
============ invoke transaction as postman@org3 ============

[2018-11-22 07:43:26.770] [DEBUG] invoke-chaincode - Sending transaction proposal "{"_nonce":"YBYms35YSyX9/OjJnT8478NKbxM6BzWi","_transaction_id":"5954ae6f3b50b944744998b52ce59a93fa431527024bc85f03dd60c92cffbd32","_admin":false}"
[2018-11-22 07:43:26.792] [INFO] invoke-chaincode - transaction proposal was good
[2018-11-22 07:43:26.792] [DEBUG] invoke-chaincode - Successfully sent Proposal and received ProposalResponse: Status - 200, message - "", metadata - "{"status":14001,"message":"Success Asset Registration"}", endorsement signature: MEQCIDhkncN8U5X+sD9TO6ubtjEdpMjKn/t1Wo11FwIB4uFsAiATS7X0V705w4YrmsTK9U34N0xHbhfALy7MZ0LaXDOa8Q==
[2018-11-22 07:43:26.793] [DEBUG] invoke-chaincode - Committing transaction "{"_nonce":"YBYms35YSyX9/OjJnT8478NKbxM6BzWi","_transaction_id":"5954ae6f3b50b944744998b52ce59a93fa431527024bc85f03dd60c92cffbd32","_admin":false}"
error: [Orderer.js]: sendBroadcast - timed out after:45000
500
Request failed: POST /channels/honeybeechannel/chaincodes/tracecc: REQUEST_TIMEOUT
Error: REQUEST_TIMEOUT
    at Timeout._onTimeout (/usr/src/app/node_modules/fabric-client/lib/Orderer.js:103:20)
    at ontimeout (timers.js:386:14)
    at tryOnTimeout (timers.js:250:5)
    at Timer.listOnTimeout (timers.js:214:5)
Error: REQUEST_TIMEOUT
    at Timeout._onTimeout (/usr/src/app/node_modules/fabric-client/lib/Orderer.js:103:20)
    at ontimeout (timers.js:386:14)
    at tryOnTimeout (timers.js:250:5)
    at Timer.listOnTimeout (timers.js:214:5)
error: [Orderer.js]: sendBroadcast - on error: "Error: 14 UNAVAILABLE: TCP Read failed\n    at createStatusError (/usr/src/app/node_modules/grpc/src/client.js:64:15)\n    at ClientDuplexStream._emitStatusIfDone (/usr/src/app/node_modules/grpc/src/client.js:270:19)\n    at ClientDuplexStream._receiveStatus (/usr/src/app/node_modules/grpc/src/client.js:248:8)\n    at /usr/src/app/node_modules/grpc/src/client.js:804:12"

Orderer 컨테이너 의심 로그 (hyperledger-new-003 기준 로그)

2018-11-22 08:46:51.709 UTC [orderer/consensus/kafka/sarama] handleResponse -> DEBU 0ab producer/broker/2 state change to [closing] because EOF
2018-11-22 08:46:51.709 UTC [orderer/consensus/kafka/sarama] handleError -> DEBU 0ac Closed connection to broker <서버의 IP주소>:9092
2018-11-22 08:46:51.709 UTC [orderer/consensus/kafka/sarama] dispatch -> DEBU 0ad producer/leader/honeybeechannel/0 state change to [retrying-1]
2018-11-22 08:46:51.709 UTC [orderer/consensus/kafka/sarama] dispatch -> DEBU 0ae producer/leader/honeybeechannel/0 abandoning broker 2
2018-11-22 08:46:51.709 UTC [orderer/consensus/kafka/sarama] run -> DEBU 0af producer/broker/2 shut down
2018-11-22 08:46:51.810 UTC [orderer/consensus/kafka/sarama] RefreshMetadata -> DEBU 0b0 client/metadata fetching metadata for [honeybeechannel] from broker <IP주소>:9092
2018-11-22 08:46:51.811 UTC [orderer/consensus/kafka/sarama] Open -> DEBU 0b1 ClientID is the default of 'sarama', you should consider setting it to something application-specific.
2018-11-22 08:46:51.811 UTC [orderer/consensus/kafka/sarama] run)-fm -> DEBU 0b2 producer/broker/2 starting up
2018-11-22 08:46:51.811 UTC [orderer/consensus/kafka/sarama] run)-fm -> DEBU 0b3 producer/broker/2 state change to [open] on honeybeechannel/0
2018-11-22 08:46:51.811 UTC [orderer/consensus/kafka/sarama] dispatch)-fm -> DEBU 0b4 producer/leader/honeybeechannel/0 selected broker 2
2018-11-22 08:46:51.811 UTC [orderer/consensus/kafka/sarama] dispatch -> DEBU 0b5 producer/leader/honeybeechannel/0 state change to [flushing-1]
2018-11-22 08:46:51.811 UTC [orderer/consensus/kafka/sarama] dispatch -> DEBU 0b6 producer/leader/honeybeechannel/0 state change to [normal]
2018-11-22 08:46:51.813 UTC [orderer/consensus/kafka/sarama] withRecover -> DEBU 0b7 Connected to broker at <서버의 IP주소>:9092 (registered as #2)

원인 파악 및 해결 방법

원인 파악

fabric-rest API를 시작하고 13분 정도가 지나면 POST 오류가 발생하나, 10분 이내에 계속 데이터를 POST하면 오류가 발생하지 않음

Orderer, Peer, EventHub와의 연결이 끊어져서 발생하는 오류

NCP(Naver Cloud Platform) 자체에서 응답이 없는 상태로 10분 정도가 지나면 자동으로 연결을 끊어버림 -> NCP 담당자 확인 사항

클라우드의 로드밸런스 기능과 연관 (자원 낭비를 줄여서 사용 요금을 줄이기 위해...)

• AWS : 60초

• Microsoft Azure : 3분

• NCP : 10분

해결 방법

HTTP Keep-alive 기능을 사용해 연결을 계속 유지

HTTP Keep-alive : 연결된 connection을 일정시간 동안 유지하면서 다시 연결을 요청할 때 기존에 연결된 connection을 재사용하는 옵션

fabric-rest API에서 Orderer, Peer, EventHub 생성 시 Keep-alive 옵션 추가

    {
      pem: Buffer.from(data).toString(),
      'ssl-target-name-override': ORGS[orgID][peerID]['server-hostname'],
      'grpc.http2.max_pings_without_data': 0,
      'grpc.max_pings_without_data': 0,
      'grpc.http2.keepalive_time': 90,
      'grpc.keepalive_time_ms': 90000,
      'grpc.http2.keepalive_timeout': 20,
      'grpc.keepalive_timeout_ms': 20000,
      'grpc.http2.min_time_between_pings_ms': 90000,
      'grpc.min_time_between_pings_ms': 90000,
      'grpc.http2.keepalive_permit_without_calls': 1,
      'grpc.keepalive_permit_without_calls': 1
    }

소스 코드 예시

function _setupPeer(orgID, peerID){
  let data = fs.readFileSync(path.join(CONFIG_DIR, ORGS[orgID][peerID]['tls_cacerts']));
  let peer = new Peer( ORGS[orgID][peerID].requests,
    {
      pem: Buffer.from(data).toString(),
      'ssl-target-name-override': ORGS[orgID][peerID]['server-hostname'],
      'grpc.http2.max_pings_without_data': 0,
      'grpc.max_pings_without_data': 0,
      'grpc.http2.keepalive_time': 90,
      'grpc.keepalive_time_ms': 90000,
      'grpc.http2.keepalive_timeout': 20,
      'grpc.keepalive_timeout_ms': 20000,
      'grpc.http2.min_time_between_pings_ms': 90000,
      'grpc.min_time_between_pings_ms': 90000,
      'grpc.http2.keepalive_permit_without_calls': 1,
      'grpc.keepalive_permit_without_calls': 1
    }
  );
  return peer;
}