Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Peer node crashes down after recieving fuzzed messages #280

Open
sardChen opened this issue Feb 18, 2022 · 1 comment
Open

Peer node crashes down after recieving fuzzed messages #280

sardChen opened this issue Feb 18, 2022 · 1 comment

Comments

@sardChen
Copy link

System information:
version: fabric 1.4
consensus type: smartbft
OS: ubuntu 20.04

Experiments setup:
Using first-network in https://github.com/SmartBFT-Go/fabric-samples, set up a 12-nodes(10 orderers and 2 peers) network locally, node1, node3, node5 are fuzzer nodes that continuously send fuzzed messages to others nodes, and the rest nodes are normal nodes.

Expected behavior:
Normal nodes run as usual.

Actual behaviour:
two peer nodes crash down, and can not be recovered.

log info:

2022-02-15 02:47:59.855 UTC [nodeCmd] serve -> INFO 001 Starting peer:
 Version: 1.4.7
 Commit SHA: 098ad50d5
 Go version: go1.14.12
 OS/Arch: linux/amd64
 Chaincode:
  Base Image Version: 0.4.22
  Base Docker Namespace: hyperledger
  Base Docker Label: org.hyperledger.fabric
  Docker Namespace: hyperledger
2022-02-15 02:47:59.855 UTC [ledgermgmt] initialize -> INFO 002 Initializing ledger mgmt
2022-02-15 02:47:59.855 UTC [kvledger] NewProvider -> INFO 003 Initializing ledger provider
2022-02-15 02:48:01.128 UTC [kvledger] NewProvider -> INFO 004 ledger provider Initialized
2022-02-15 02:48:03.388 UTC [ledgermgmt] initialize -> INFO 005 ledger mgmt initialized
2022-02-15 02:48:03.389 UTC [peer] func1 -> INFO 006 Auto-detected peer address: 192.168.64.7:8051
2022-02-15 02:48:03.389 UTC [peer] func1 -> INFO 007 Returning peer1.org1.example.com:8051
2022-02-15 02:48:03.389 UTC [peer] func1 -> INFO 008 Auto-detected peer address: 192.168.64.7:8051
2022-02-15 02:48:03.389 UTC [peer] func1 -> INFO 009 Returning peer1.org1.example.com:8051
2022-02-15 02:48:03.390 UTC [nodeCmd] serve -> INFO 00a Starting peer with TLS enabled
2022-02-15 02:48:03.391 UTC [nodeCmd] computeChaincodeEndpoint -> INFO 00b Entering computeChaincodeEndpoint with peerHostname: peer1.org1.example.com
2022-02-15 02:48:03.391 UTC [nodeCmd] computeChaincodeEndpoint -> INFO 00c Exit with ccEndpoint: peer1.org1.example.com:8052
2022-02-15 02:48:03.393 UTC [sccapi] registerSysCC -> INFO 00d system chaincode lscc(github.com/hyperledger/fabric/core/scc/lscc) registered
2022-02-15 02:48:03.393 UTC [sccapi] registerSysCC -> INFO 00e system chaincode cscc(github.com/hyperledger/fabric/core/scc/cscc) registered
2022-02-15 02:48:03.393 UTC [sccapi] registerSysCC -> INFO 00f system chaincode qscc(github.com/hyperledger/fabric/core/scc/qscc) registered
2022-02-15 02:48:03.393 UTC [sccapi] registerSysCC -> INFO 010 system chaincode (+lifecycle,github.com/hyperledger/fabric/core/chaincode/lifecycle,true) disabled
2022-02-15 02:48:03.395 UTC [gossip.service] func1 -> INFO 011 Initialize gossip with endpoint peer1.org1.example.com:8051 and bootstrap set [peer0.org1.example.com:7051]
2022-02-15 02:48:03.397 UTC [gossip.gossip] NewGossipService -> INFO 012 Creating gossip service with self membership of Endpoint: peer1.org1.example.com:8051, InternalEndpoint: peer1.org1.example.com:8051, PKI-ID: 6f51d097abf4a2395cae772e43ad9b0c02588aa51250ff218be596025eb1cc36, Metadata: 
2022-02-15 02:48:03.397 UTC [gossip.gossip] start -> INFO 013 Gossip instance peer1.org1.example.com:8051 started
2022-02-15 02:48:03.398 UTC [sccapi] deploySysCC -> INFO 014 system chaincode lscc/(github.com/hyperledger/fabric/core/scc/lscc) deployed
2022-02-15 02:48:03.398 UTC [cscc] Init -> INFO 015 Init CSCC
2022-02-15 02:48:03.398 UTC [sccapi] deploySysCC -> INFO 016 system chaincode cscc/(github.com/hyperledger/fabric/core/scc/cscc) deployed
2022-02-15 02:48:03.398 UTC [qscc] Init -> INFO 017 Init QSCC
2022-02-15 02:48:03.398 UTC [sccapi] deploySysCC -> INFO 018 system chaincode qscc/(github.com/hyperledger/fabric/core/scc/qscc) deployed
2022-02-15 02:48:03.398 UTC [sccapi] deploySysCC -> INFO 019 system chaincode (+lifecycle,github.com/hyperledger/fabric/core/chaincode/lifecycle) disabled
2022-02-15 02:48:03.398 UTC [nodeCmd] serve -> INFO 01a Deployed system chaincodes
2022-02-15 02:48:03.399 UTC [discovery] NewService -> INFO 01b Created with config TLS: true, authCacheMaxSize: 1000, authCachePurgeRatio: 0.750000
2022-02-15 02:48:03.399 UTC [nodeCmd] registerDiscoveryService -> INFO 01c Discovery service activated
2022-02-15 02:48:03.399 UTC [nodeCmd] serve -> INFO 01d Starting peer with ID=[name:"peer1.org1.example.com" ], network ID=[dev], address=[peer1.org1.example.com:8051]
2022-02-15 02:48:03.399 UTC [nodeCmd] serve -> INFO 01e Started peer with ID=[name:"peer1.org1.example.com" ], network ID=[dev], address=[peer1.org1.example.com:8051]
2022-02-15 02:48:03.399 UTC [nodeCmd] func8 -> INFO 01f Starting profiling server with listenAddress = 0.0.0.0:6060
2022-02-15 02:48:03.399 UTC [kvledger] LoadPreResetHeight -> INFO 020 Loading prereset height from path [/var/hyperledger/production/ledgersData/chains]
2022-02-15 02:48:03.400 UTC [fsblkstorage] LoadPreResetHeight -> INFO 021 Loading Pre-reset heights
2022-02-15 02:48:03.400 UTC [fsblkstorage] preRestHtFiles -> INFO 022 Dir [/var/hyperledger/production/ledgersData/chains/chains] missing... exiting
2022-02-15 02:48:03.400 UTC [fsblkstorage] LoadPreResetHeight -> INFO 023 Pre-reset heights loaded
2022-02-15 02:48:06.398 UTC [gossip.discovery] func1 -> WARN 024 Could not connect to Endpoint: peer0.org1.example.com:7051, InternalEndpoint: peer0.org1.example.com:7051, PKI-ID: <nil>, Metadata:  : context deadline exceeded
2022-02-15 02:48:08.544 UTC [comm.grpc.server] 1 -> INFO 025 unary call completed grpc.service=gossip.Gossip grpc.method=Ping grpc.request_deadline=2022-02-15T02:48:10.544Z grpc.peer_address=192.168.64.13:40506 grpc.peer_subject="CN=peer0.org1.example.com,L=San Francisco,ST=California,C=US" grpc.code=OK grpc.call_duration=47.55µs
2022-02-15 02:48:08.545 UTC [comm.grpc.server] 1 -> INFO 026 streaming call completed grpc.service=gossip.Gossip grpc.method=GossipStream grpc.request_deadline=2022-02-15T02:48:18.544Z grpc.peer_address=192.168.64.13:40506 grpc.peer_subject="CN=peer0.org1.example.com,L=San Francisco,ST=California,C=US" error="rpc error: code = Canceled desc = context canceled" grpc.code=Canceled grpc.call_duration=967.734µs
2022-02-15 02:48:08.548 UTC [comm.grpc.server] 1 -> INFO 027 unary call completed grpc.service=gossip.Gossip grpc.method=Ping grpc.request_deadline=2022-02-15T02:48:10.548Z grpc.peer_address=192.168.64.13:40514 grpc.peer_subject="CN=peer0.org1.example.com,L=San Francisco,ST=California,C=US" grpc.code=OK grpc.call_duration=26.914µs
2022-02-15 02:48:31.405 UTC [comm.grpc.server] 1 -> INFO 028 streaming call completed grpc.service=gossip.Gossip grpc.method=GossipStream grpc.peer_address=192.168.64.13:40514 grpc.peer_subject="CN=peer0.org1.example.com,L=San Francisco,ST=California,C=US" error="rpc error: code = Canceled desc = context canceled" grpc.code=Canceled grpc.call_duration=22.856951692s
2022-02-15 02:48:31.800 UTC [endorser] callChaincode -> INFO 029 [][5a2a0c8e] Entry chaincode: name:"cscc" 
2022-02-15 02:48:31.801 UTC [ledgermgmt] CreateLedger -> INFO 02a Creating ledger [mychannel] with genesis block
2022-02-15 02:48:31.853 UTC [fsblkstorage] newBlockfileMgr -> INFO 02b Getting block information from block storage
2022-02-15 02:48:32.187 UTC [kvledger] CommitWithPvtData -> INFO 02c [mychannel] Committed block [0] with 1 transaction(s) in 250ms (state_validation=1ms block_and_pvtdata_commit=165ms state_commit=42ms) commitHash=[]
2022-02-15 02:48:32.229 UTC [ledgermgmt] CreateLedger -> INFO 02d Created ledger [mychannel] with genesis block
2022-02-15 02:48:32.235 UTC [gossip.gossip] JoinChan -> INFO 02e Joining gossip network of channel mychannel with 2 organizations
2022-02-15 02:48:32.235 UTC [gossip.gossip] learnAnchorPeers -> INFO 02f No configured anchor peers of Org1MSP for channel mychannel to learn about
2022-02-15 02:48:32.235 UTC [gossip.gossip] learnAnchorPeers -> INFO 030 No configured anchor peers of Org2MSP for channel mychannel to learn about
2022-02-15 02:48:32.358 UTC [gossip.state] NewGossipStateProvider -> INFO 031 Updating metadata information for channel mychannel, current ledger sequence is at = 0, next expected block is = 1
2022-02-15 02:48:32.359 UTC [sccapi] deploySysCC -> INFO 032 system chaincode lscc/mychannel(github.com/hyperledger/fabric/core/scc/lscc) deployed
2022-02-15 02:48:32.359 UTC [cscc] Init -> INFO 033 Init CSCC
2022-02-15 02:48:32.359 UTC [sccapi] deploySysCC -> INFO 034 system chaincode cscc/mychannel(github.com/hyperledger/fabric/core/scc/cscc) deployed
2022-02-15 02:48:32.359 UTC [qscc] Init -> INFO 035 Init QSCC
2022-02-15 02:48:32.359 UTC [sccapi] deploySysCC -> INFO 036 system chaincode qscc/mychannel(github.com/hyperledger/fabric/core/scc/qscc) deployed
2022-02-15 02:48:32.359 UTC [sccapi] deploySysCC -> INFO 037 system chaincode (+lifecycle,github.com/hyperledger/fabric/core/chaincode/lifecycle) disabled
2022-02-15 02:48:32.359 UTC [endorser] callChaincode -> INFO 038 [][5a2a0c8e] Exit chaincode: name:"cscc"  (560ms)
2022-02-15 02:48:32.359 UTC [comm.grpc.server] 1 -> INFO 039 unary call completed grpc.service=protos.Endorser grpc.method=ProcessProposal grpc.peer_address=192.168.64.16:44830 grpc.code=OK grpc.call_duration=560.424456ms
2022-02-15 02:48:34.741 UTC [gossip.election] leaderElection -> INFO 03a 6f51d097abf4a2395cae772e43ad9b0c02588aa51250ff218be596025eb1cc36 : Some peer is already a leader
2022-02-15 02:48:37.235 UTC [gossip.channel] reportMembershipChanges -> INFO 03b Membership view has changed. peers went online:  [[peer0.org1.example.com:7051]] , current view:  [[peer0.org1.example.com:7051]]
2022-02-15 02:48:43.745 UTC [policies.ImplicitOrderer] BFTEvaluate -> DEBU 03c SignatureSet size: 7, nodeCount: 0
2022-02-15 02:48:43.753 UTC [gossip.privdata] StoreBlock -> INFO 03d [mychannel] Received block [1] from buffer
2022-02-15 02:48:43.756 UTC [gossip.gossip] JoinChan -> INFO 03e Joining gossip network of channel mychannel with 2 organizations
2022-02-15 02:48:43.756 UTC [gossip.gossip] learnAnchorPeers -> INFO 03f Learning about the configured anchor peers of Org1MSP for channel mychannel : [{peer0.org1.example.com 7051}]
2022-02-15 02:48:43.756 UTC [gossip.gossip] learnAnchorPeers -> INFO 040 No configured anchor peers of Org2MSP for channel mychannel to learn about
2022-02-15 02:48:43.757 UTC [committer.txvalidator] Validate -> INFO 041 [mychannel] Validated block [1] in 4ms
2022-02-15 02:48:43.759 UTC [gossip.comm] func1 -> WARN 042 peer0.org1.example.com:7051, PKIid:1a51ca5af6a532977bab3fb4afe0cfebe441f02850bb461e8d316be01852880f isn't responsive: EOF
2022-02-15 02:48:43.759 UTC [gossip.discovery] expireDeadMembers -> WARN 043 Entering [1a51ca5af6a532977bab3fb4afe0cfebe441f02850bb461e8d316be01852880f]
2022-02-15 02:48:43.759 UTC [gossip.discovery] expireDeadMembers -> WARN 044 Closing connection to Endpoint: peer0.org1.example.com:7051, InternalEndpoint: peer0.org1.example.com:7051, PKI-ID: 1a51ca5af6a532977bab3fb4afe0cfebe441f02850bb461e8d316be01852880f, Metadata: 
2022-02-15 02:48:43.759 UTC [gossip.discovery] expireDeadMembers -> WARN 045 Exiting
2022-02-15 02:48:43.890 UTC [comm.grpc.server] 1 -> INFO 046 unary call completed grpc.service=gossip.Gossip grpc.method=Ping grpc.request_deadline=2022-02-15T02:48:45.89Z grpc.peer_address=192.168.64.13:40822 grpc.peer_subject="CN=peer0.org1.example.com,L=San Francisco,ST=California,C=US" grpc.code=OK grpc.call_duration=38.77µs
2022-02-15 02:48:43.890 UTC [gossip.gossip] validateMsg -> WARN 047 StateInfo message GossipMessage: tag:CHAN_OR_ORG state_info:<timestamp:<inc_num:1644893319881886185 seq_num:1644893319992212163 > pki_id:"\321sRX}\2565\211\267V\331\271\347p\236\366-@\354jJ\242\346]1\232\375\356\337&G^" channel_MAC:"=\224N\031\267\201\221\264\003\024/9\271s\352,\374f\376\314\337\r'II8\262\345\235\372\177\235" properties:<ledger_height:1 > > , Envelope: 98 bytes, Signature: 70 bytes is found invalid: PKIID wasn't found
2022-02-15 02:48:43.890 UTC [gossip.gossip] handleMessage -> WARN 048 Message GossipMessage: tag:CHAN_OR_ORG state_info:<timestamp:<inc_num:1644893319881886185 seq_num:1644893319992212163 > pki_id:"\321sRX}\2565\211\267V\331\271\347p\236\366-@\354jJ\242\346]1\232\375\356\337&G^" channel_MAC:"=\224N\031\267\201\221\264\003\024/9\271s\352,\374f\376\314\337\r'II8\262\345\235\372\177\235" properties:<ledger_height:1 > > , Envelope: 98 bytes, Signature: 70 bytes isn't valid
2022-02-15 02:48:44.373 UTC [kvledger] CommitWithPvtData -> INFO 049 [mychannel] Committed block [1] with 1 transaction(s) in 615ms (state_validation=0ms block_and_pvtdata_commit=389ms state_commit=139ms) commitHash=[47dc540c94ceb704a23875c11273e16bb0b8a87aed84de911f2133568115f254]
2022-02-15 02:48:48.424 UTC [comm.grpc.server] 1 -> INFO 04a unary call completed grpc.service=gossip.Gossip grpc.method=Ping grpc.request_deadline=2022-02-15T02:48:50.424Z grpc.peer_address=192.168.64.2:55070 grpc.peer_subject="CN=peer1.org2.example.com,L=San Francisco,ST=California,C=US" grpc.code=OK grpc.call_duration=65.812µs
2022-02-15 02:48:48.428 UTC [comm.grpc.server] 1 -> INFO 04b unary call completed grpc.service=gossip.Gossip grpc.method=Ping grpc.request_deadline=2022-02-15T02:48:50.427Z grpc.peer_address=192.168.64.15:56192 grpc.peer_subject="CN=peer0.org2.example.com,L=San Francisco,ST=California,C=US" grpc.code=OK grpc.call_duration=34.629µs
2022-02-15 02:48:48.812 UTC [policies.ImplicitOrderer] BFTEvaluate -> DEBU 04c SignatureSet size: 7, nodeCount: 0
2022-02-15 02:48:48.819 UTC [gossip.privdata] StoreBlock -> INFO 04d [mychannel] Received block [2] from buffer
2022-02-15 02:48:48.822 UTC [gossip.gossip] JoinChan -> INFO 04e Joining gossip network of channel mychannel with 2 organizations
2022-02-15 02:48:48.822 UTC [gossip.gossip] learnAnchorPeers -> INFO 04f Learning about the configured anchor peers of Org2MSP for channel mychannel : [{peer0.org2.example.com 9051}]
2022-02-15 02:48:48.822 UTC [gossip.gossip] learnAnchorPeers -> INFO 050 Learning about the configured anchor peers of Org1MSP for channel mychannel : [{peer0.org1.example.com 7051}]
2022-02-15 02:48:48.823 UTC [committer.txvalidator] Validate -> INFO 051 [mychannel] Validated block [2] in 3ms
2022-02-15 02:48:48.824 UTC [comm.grpc.server] 1 -> INFO 052 streaming call completed grpc.service=gossip.Gossip grpc.method=GossipStream grpc.peer_address=192.168.64.13:40822 grpc.peer_subject="CN=peer0.org1.example.com,L=San Francisco,ST=California,C=US" error="rpc error: code = Canceled desc = context canceled" grpc.code=Canceled grpc.call_duration=4.934465697s
2022-02-15 02:48:48.825 UTC [comm.grpc.server] 1 -> INFO 053 streaming call completed grpc.service=gossip.Gossip grpc.method=GossipStream grpc.peer_address=192.168.64.15:56192 grpc.peer_subject="CN=peer0.org2.example.com,L=San Francisco,ST=California,C=US" error=EOF grpc.code=Unknown grpc.call_duration=397.290014ms
2022-02-15 02:48:49.568 UTC [kvledger] CommitWithPvtData -> INFO 054 [mychannel] Committed block [2] with 1 transaction(s) in 744ms (state_validation=0ms block_and_pvtdata_commit=469ms state_commit=192ms) commitHash=[5f88b61407b149a48413433f4670c46531e5c4a8febdc339a9536ff8716a559e]
2022-02-15 02:48:52.235 UTC [gossip.channel] reportMembershipChanges -> INFO 055 Membership view has changed. peers went online:  [[peer1.org2.example.com:10051 ]] , current view:  [[peer0.org1.example.com:7051] [peer1.org2.example.com:10051 ]]
2022-02-15 02:48:52.623 UTC [policies.ImplicitOrderer] BFTEvaluate -> DEBU 056 SignatureSet size: 7, nodeCount: 0
2022-02-15 02:48:52.629 UTC [gossip.privdata] StoreBlock -> INFO 057 [mychannel] Received block [3] from buffer
2022-02-15 02:48:52.630 UTC [cauthdsl] deduplicate -> WARN 058 De-duplicating identity [OrdererMSP0100cd56b1f451a660965a5b2003f96981149df5fedb16975e2da2859f71d4b9] at index 1 in signature set
2022-02-15 02:48:52.633 UTC [committer.txvalidator] Validate -> INFO 059 [mychannel] Validated block [3] in 3ms
2022-02-15 02:48:53.366 UTC [kvledger] CommitWithPvtData -> INFO 05a [mychannel] Committed block [3] with 1 transaction(s) in 732ms (state_validation=0ms block_and_pvtdata_commit=517ms state_commit=139ms) commitHash=[37be5332b9300ef2e301f0e0e5385a0a729d3fef5c9ea4a7bd4766bb91998a31]
2022-02-15 02:48:57.235 UTC [gossip.channel] reportMembershipChanges -> INFO 05b Membership view has changed. peers went online:  [[peer0.org2.example.com:9051 ]] , current view:  [[peer0.org1.example.com:7051] [peer1.org2.example.com:10051 ] [peer0.org2.example.com:9051 ]]
2022-02-15 02:49:16.460 UTC [policies.ImplicitOrderer] BFTEvaluate -> DEBU 05c SignatureSet size: 7, nodeCount: 0
2022-02-15 02:49:16.467 UTC [gossip.privdata] StoreBlock -> INFO 05d [mychannel] Received block [4] from buffer
2022-02-15 02:49:16.481 UTC [committer.txvalidator] Validate -> INFO 05e [mychannel] Validated block [4] in 13ms
2022-02-15 02:49:16.485 UTC [cceventmgmt] HandleStateUpdates -> INFO 05f Channel [mychannel]: Handling deploy or update of chaincode [mycc]
2022-02-15 02:49:16.485 UTC [ccprovider] ExtractStatedbArtifactsForChaincode -> INFO 060 Error while loading installation package for ccname=mycc, ccversion=1.0. Err=open /var/hyperledger/production/chaincodes/mycc.1.0: no such file or directory
2022-02-15 02:49:16.485 UTC [cceventmgmt] HandleChaincodeDeploy -> INFO 061 Channel [mychannel]: Chaincode [Name=mycc, Version=1.0, Hash=[]byte{0x33, 0x3a, 0x19, 0xb1, 0x10, 0x63, 0xd0, 0xad, 0xe7, 0xbe, 0x69, 0x1f, 0x9f, 0x22, 0xc0, 0x4a, 0xd3, 0x69, 0xba, 0xba, 0x15, 0x66, 0xf, 0x7a, 0xe9, 0x51, 0x1f, 0xd1, 0xa6, 0x48, 0x82, 0x9}] is not installed hence no need to create chaincode artifacts for endorsement
2022-02-15 02:49:17.033 UTC [kvledger] CommitWithPvtData -> INFO 062 [mychannel] Committed block [4] with 1 transaction(s) in 547ms (state_validation=0ms block_and_pvtdata_commit=371ms state_commit=100ms) commitHash=[af8cf0c2af2fd0ccca9dd4ca301568af8cc599fe4b29dc395675c2218f9adebe]
2022-02-15 02:57:13.282 UTC [policies.ImplicitOrderer] BFTEvaluate -> DEBU 063 SignatureSet size: 7, nodeCount: 0
2022-02-15 02:57:13.285 UTC [gossip.privdata] StoreBlock -> INFO 064 [mychannel] Received block [5] from buffer
2022-02-15 02:57:13.285 UTC [committer.txvalidator] checkTxIdDupsLedger -> ERRO 065 Duplicate transaction found,  23e6f01412d2eb836fbf88629813a0e256d63cfee2358c4dc15772f9b8adf752 , skipping
2022-02-15 02:57:13.285 UTC [committer.txvalidator] Validate -> INFO 066 [mychannel] Validated block [5] in 0ms
2022-02-15 02:57:13.285 UTC [valimpl] preprocessProtoBlock -> WARN 067 Channel [mychannel]: Block [5] Transaction index [1] TxId [23e6f01412d2eb836fbf88629813a0e256d63cfee2358c4dc15772f9b8adf752] marked as invalid by committer. Reason code [DUPLICATE_TXID]
2022-02-15 02:57:13.829 UTC [kvledger] CommitWithPvtData -> INFO 068 [mychannel] Committed block [5] with 2 transaction(s) in 543ms (state_validation=0ms block_and_pvtdata_commit=385ms state_commit=82ms) commitHash=[fda8341689858c8a091238a00b31eeb37a65400c47b98e50b8e1ae5fca2cf13a]
2022-02-15 02:59:26.738 UTC [policies.ImplicitOrderer] BFTEvaluate -> DEBU 069 SignatureSet size: 7, nodeCount: 0
2022-02-15 02:59:26.740 UTC [gossip.privdata] StoreBlock -> INFO 06a [mychannel] Received block [6] from buffer
2022-02-15 02:59:26.747 UTC [committer.txvalidator] checkTxIdDupsLedger -> ERRO 06b Duplicate transaction found,  75f2c2ba5abf72554b8b64c496c59988c0ea82e03fb6dbe1f5a5a73234683dad , skipping
2022-02-15 02:59:26.747 UTC [committer.txvalidator] Validate -> INFO 06c [mychannel] Validated block [6] in 0ms
2022-02-15 02:59:26.747 UTC [valimpl] preprocessProtoBlock -> WARN 06d Channel [mychannel]: Block [6] Transaction index [0] TxId [75f2c2ba5abf72554b8b64c496c59988c0ea82e03fb6dbe1f5a5a73234683dad] marked as invalid by committer. Reason code [DUPLICATE_TXID]
2022-02-15 02:59:27.236 UTC [kvledger] CommitWithPvtData -> INFO 06e [mychannel] Committed block [6] with 1 transaction(s) in 489ms (state_validation=0ms block_and_pvtdata_commit=350ms state_commit=72ms) commitHash=[7175d03a92861c92f0875473b706674e146f648736a958cf468c1fb63c9788b7]
2022-02-15 03:05:10.007 UTC [policies.ImplicitOrderer] BFTEvaluate -> DEBU 06f SignatureSet size: 7, nodeCount: 0
2022-02-15 03:05:10.015 UTC [gossip.privdata] StoreBlock -> INFO 070 [mychannel] Received block [7] from buffer
2022-02-15 03:05:10.016 UTC [committer.txvalidator] checkTxIdDupsLedger -> ERRO 071 Duplicate transaction found,  23e6f01412d2eb836fbf88629813a0e256d63cfee2358c4dc15772f9b8adf752 , skipping
2022-02-15 03:05:10.016 UTC [committer.txvalidator] Validate -> INFO 072 [mychannel] Validated block [7] in 0ms
2022-02-15 03:05:10.016 UTC [valimpl] preprocessProtoBlock -> WARN 073 Channel [mychannel]: Block [7] Transaction index [0] TxId [23e6f01412d2eb836fbf88629813a0e256d63cfee2358c4dc15772f9b8adf752] marked as invalid by committer. Reason code [DUPLICATE_TXID]
2022-02-15 03:05:10.499 UTC [kvledger] CommitWithPvtData -> INFO 074 [mychannel] Committed block [7] with 1 transaction(s) in 483ms (state_validation=0ms block_and_pvtdata_commit=348ms state_commit=58ms) commitHash=[aa95d4977eeafe46e8339f432044e4752bfa054502dea029223e6231f821e028]
2022-02-15 03:05:34.837 UTC [policies.ImplicitOrderer] BFTEvaluate -> DEBU 075 SignatureSet size: 7, nodeCount: 0
2022-02-15 03:05:34.838 UTC [gossip.privdata] StoreBlock -> INFO 076 [mychannel] Received block [8] from buffer
2022-02-15 03:05:34.838 UTC [committer.txvalidator] checkTxIdDupsLedger -> ERRO 077 Duplicate transaction found,  75f2c2ba5abf72554b8b64c496c59988c0ea82e03fb6dbe1f5a5a73234683dad , skipping
2022-02-15 03:05:34.839 UTC [committer.txvalidator] Validate -> INFO 078 [mychannel] Validated block [8] in 0ms
2022-02-15 03:05:34.839 UTC [valimpl] preprocessProtoBlock -> WARN 079 Channel [mychannel]: Block [8] Transaction index [0] TxId [75f2c2ba5abf72554b8b64c496c59988c0ea82e03fb6dbe1f5a5a73234683dad] marked as invalid by committer. Reason code [DUPLICATE_TXID]
2022-02-15 03:05:35.677 UTC [kvledger] CommitWithPvtData -> INFO 07a [mychannel] Committed block [8] with 1 transaction(s) in 838ms (state_validation=0ms block_and_pvtdata_commit=621ms state_commit=117ms) commitHash=[14d1f5d1401a9c4e29888f86edb4752aa2d5c9f4a0f51005554b1f99988f4301]
2022-02-15 03:05:58.737 UTC [policies.ImplicitOrderer] BFTEvaluate -> DEBU 07b SignatureSet size: 7, nodeCount: 0
2022-02-15 03:05:58.738 UTC [gossip.privdata] StoreBlock -> INFO 07c [mychannel] Received block [9] from buffer
2022-02-15 03:05:58.743 UTC [committer.txvalidator] validateTx -> ERRO 07d config currently at sequence 4, cannot validate config at sequence 2
github.com/hyperledger/fabric/common/configtx.(*ValidatorImpl).Validate
  /opt/gopath/src/github.com/hyperledger/fabric/common/configtx/validator.go:170
github.com/hyperledger/fabric/core/peer.(*chainSupport).Apply
  /opt/gopath/src/github.com/hyperledger/fabric/core/peer/peer.go:143
github.com/hyperledger/fabric/core/committer/txvalidator.(*TxValidator).validateTx
  /opt/gopath/src/github.com/hyperledger/fabric/core/committer/txvalidator/validator.go:425
github.com/hyperledger/fabric/core/committer/txvalidator.(*TxValidator).Validate.func1.1
  /opt/gopath/src/github.com/hyperledger/fabric/core/committer/txvalidator/validator.go:158
runtime.goexit
  /opt/go/src/runtime/asm_amd64.s:1373
error validating config which passed initial validity checks
2022-02-15 03:05:58.743 UTC [gossip.privdata] StoreBlock -> ERRO 07e Validation failed: config currently at sequence 4, cannot validate config at sequence 2
github.com/hyperledger/fabric/common/configtx.(*ValidatorImpl).Validate
  /opt/gopath/src/github.com/hyperledger/fabric/common/configtx/validator.go:170
github.com/hyperledger/fabric/core/peer.(*chainSupport).Apply
  /opt/gopath/src/github.com/hyperledger/fabric/core/peer/peer.go:143
github.com/hyperledger/fabric/core/committer/txvalidator.(*TxValidator).validateTx
  /opt/gopath/src/github.com/hyperledger/fabric/core/committer/txvalidator/validator.go:425
github.com/hyperledger/fabric/core/committer/txvalidator.(*TxValidator).Validate.func1.1
  /opt/gopath/src/github.com/hyperledger/fabric/core/committer/txvalidator/validator.go:158
runtime.goexit
  /opt/go/src/runtime/asm_amd64.s:1373
error validating config which passed initial validity checks
2022-02-15 03:05:58.743 UTC [gossip.state] commitBlock -> ERRO 07f Got error while committing(config currently at sequence 4, cannot validate config at sequence 2
github.com/hyperledger/fabric/common/configtx.(*ValidatorImpl).Validate
  /opt/gopath/src/github.com/hyperledger/fabric/common/configtx/validator.go:170
github.com/hyperledger/fabric/core/peer.(*chainSupport).Apply
  /opt/gopath/src/github.com/hyperledger/fabric/core/peer/peer.go:143
github.com/hyperledger/fabric/core/committer/txvalidator.(*TxValidator).validateTx
  /opt/gopath/src/github.com/hyperledger/fabric/core/committer/txvalidator/validator.go:425
github.com/hyperledger/fabric/core/committer/txvalidator.(*TxValidator).Validate.func1.1
  /opt/gopath/src/github.com/hyperledger/fabric/core/committer/txvalidator/validator.go:158
runtime.goexit
  /opt/go/src/runtime/asm_amd64.s:1373
error validating config which passed initial validity checks
github.com/hyperledger/fabric/gossip/state.(*GossipStateProviderImpl).commitBlock
  /opt/gopath/src/github.com/hyperledger/fabric/gossip/state/state.go:811
github.com/hyperledger/fabric/gossip/state.(*GossipStateProviderImpl).deliverPayloads
  /opt/gopath/src/github.com/hyperledger/fabric/gossip/state/state.go:598
runtime.goexit
  /opt/go/src/runtime/asm_amd64.s:1373)
2022-02-15 03:05:58.743 UTC [gossip.state] deliverPayloads -> PANI 080 Cannot commit block to the ledger due to config currently at sequence 4, cannot validate config at sequence 2
github.com/hyperledger/fabric/common/configtx.(*ValidatorImpl).Validate
  /opt/gopath/src/github.com/hyperledger/fabric/common/configtx/validator.go:170
github.com/hyperledger/fabric/core/peer.(*chainSupport).Apply
  /opt/gopath/src/github.com/hyperledger/fabric/core/peer/peer.go:143
github.com/hyperledger/fabric/core/committer/txvalidator.(*TxValidator).validateTx
  /opt/gopath/src/github.com/hyperledger/fabric/core/committer/txvalidator/validator.go:425
github.com/hyperledger/fabric/core/committer/txvalidator.(*TxValidator).Validate.func1.1
  /opt/gopath/src/github.com/hyperledger/fabric/core/committer/txvalidator/validator.go:158
runtime.goexit
  /opt/go/src/runtime/asm_amd64.s:1373
error validating config which passed initial validity checks
github.com/hyperledger/fabric/gossip/state.(*GossipStateProviderImpl).deliverPayloads
  /opt/gopath/src/github.com/hyperledger/fabric/gossip/state/state.go:603
runtime.goexit
  /opt/go/src/runtime/asm_amd64.s:1373
panic: Cannot commit block to the ledger due to config currently at sequence 4, cannot validate config at sequence 2
github.com/hyperledger/fabric/common/configtx.(*ValidatorImpl).Validate
  /opt/gopath/src/github.com/hyperledger/fabric/common/configtx/validator.go:170
github.com/hyperledger/fabric/core/peer.(*chainSupport).Apply
  /opt/gopath/src/github.com/hyperledger/fabric/core/peer/peer.go:143
github.com/hyperledger/fabric/core/committer/txvalidator.(*TxValidator).validateTx
  /opt/gopath/src/github.com/hyperledger/fabric/core/committer/txvalidator/validator.go:425
github.com/hyperledger/fabric/core/committer/txvalidator.(*TxValidator).Validate.func1.1
  /opt/gopath/src/github.com/hyperledger/fabric/core/committer/txvalidator/validator.go:158
runtime.goexit
  /opt/go/src/runtime/asm_amd64.s:1373
error validating config which passed initial validity checks
github.com/hyperledger/fabric/gossip/state.(*GossipStateProviderImpl).deliverPayloads
  /opt/gopath/src/github.com/hyperledger/fabric/gossip/state/state.go:603
runtime.goexit
  /opt/go/src/runtime/asm_amd64.s:1373
goroutine 341 [running]:
github.com/hyperledger/fabric/vendor/go.uber.org/zap/zapcore.(*CheckedEntry).Write(0xc002935970, 0x0, 0x0, 0x0)
  /opt/gopath/src/github.com/hyperledger/fabric/vendor/go.uber.org/zap/zapcore/entry.go:229 +0x545
github.com/hyperledger/fabric/vendor/go.uber.org/zap.(*SugaredLogger).log(0xc000286090, 0xc00013de04, 0x1a4467a, 0x2c, 0xc004421ce0, 0x1, 0x1, 0x0, 0x0, 0x0)
  /opt/gopath/src/github.com/hyperledger/fabric/vendor/go.uber.org/zap/sugar.go:234 +0x100
github.com/hyperledger/fabric/vendor/go.uber.org/zap.(*SugaredLogger).Panicf(...)
  /opt/gopath/src/github.com/hyperledger/fabric/vendor/go.uber.org/zap/sugar.go:159
github.com/hyperledger/fabric/common/flogging.(*FabricLogger).Panicf(0xc000286098, 0x1a4467a, 0x2c, 0xc004421ce0, 0x1, 0x1)
  /opt/gopath/src/github.com/hyperledger/fabric/common/flogging/zap.go:74 +0x7c
github.com/hyperledger/fabric/gossip/state.(*GossipStateProviderImpl).deliverPayloads(0xc003262fa0)
  /opt/gopath/src/github.com/hyperledger/fabric/gossip/state/state.go:603 +0x509
created by github.com/hyperledger/fabric/gossip/state.NewGossipStateProvider
  /opt/gopath/src/github.com/hyperledger/fabric/gossip/state/state.go:284 +0x844
@yacovm
Copy link

yacovm commented Mar 19, 2022

did you send a config block after another? what blocks did you send?
I don't think this is a BFT bug, it's probably a Fabric bug, but please tell what you did to reproduce this

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@sardChen @yacovm