search

SmartBFT-Go / fabric

Integration of the BFT consensus library into Fabric
Apache License 2.0
31 stars 11 forks source link

Peer node crashes down after recieving fuzzed messages #280

Open sardChen opened 2 years ago

sardChen commented 2 years ago

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 commented 2 years ago

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