search

hyperledger-archives / fabric

THIS IS A READ-ONLY historic repository. Current development is at https://gerrit.hyperledger.org/r/#/admin/projects/fabric . pull requests not accepted
https://gerrit.hyperledger.org/
Apache License 2.0
1.17k stars 1.01k forks source link

Warning with a nil pointer in VP logs #1379

Open RicHernandez2 opened 8 years ago

RicHernandez2 commented 8 years ago

Description:

On startup, a set of 4 VPs with security, running pbft sieve give a warning to a nil pointer

Logs:

vagrant@hyperledger-devenv:v0.0.9-5bdb4b6:~$ docker run --rm -it -e CORE_VM_ENDPOINT=http://172.17.0.1:4243 -e CORE_PEER_ID=vp3 -e CORE_PEER_ADDRESSAUTODETECT=true -e CORE_PEER_DISCOVERY_ROOTNODE=172.17.0.2:303 -e CORE_PEER_PKI_ECA_PADDR=172.17.0.1:50051 -e CORE_PEER_PKI_TCA_PADDR=172.17.0.1:50051 -e CORE_PEER_PKI_TLSCA_PADDR=172.17.0.1:50051 -e CORE_SECURITY_ENROLLID=test_vp7 -e CORE_SECURITY_ENROLLSECRET=twoKZouEyLyB -v /opt/logs/vp3:/go hyperledger-peer peer peer
23:58:36.856 [crypto] main -> INFO 001 Log level recognized 'info', set to INFO
23:58:36.857 [logging] LoggingInit -> DEBU 002 Setting default logging level to DEBUG for command 'peer'
23:58:36.857 [peer] func1 -> INFO 003 Auto detected peer address: 172.17.0.5:30303
23:58:36.857 [peer] func1 -> INFO 004 Auto detected peer address: 172.17.0.5:30303
23:58:36.859 [peer] func1 -> INFO 005 Auto detected peer address: 172.17.0.5:30303
23:58:36.860 [sysccapi] RegisterSysCC -> DEBU 006 system chaincode github.com/hyperledger/fabric/core/system_chaincode/sample_syscc registered
23:58:36.862 [eventhub_producer] AddEventType -> DEBU 007 registering block
23:58:36.862 [eventhub_producer] AddEventType -> DEBU 008 registering register
23:58:36.862 [eventhub_producer] start -> INFO 009 event processor started
23:58:36.863 [main] serve -> INFO 00a Security enabled status: true
23:58:36.863 [main] serve -> INFO 00b Privacy enabled status: false
23:58:36.863 [main] func1 -> DEBU 00c Registering validator with enroll ID: test_vp7
23:58:36.863 [crypto] func1 -> INFO 00d Registering validator [test_vp7] with name [test_vp7]...
23:58:36.962 [crypto] func1 -> INFO 00e Registering validator [test_vp7] with name [test_vp7]...done!
23:58:36.962 [main] func1 -> DEBU 00f Initializing validator with enroll ID: test_vp7
23:58:36.962 [crypto] func1 -> INFO 010 Initializing validator [test_vp7]...
23:58:36.974 [crypto] func1 -> INFO 011 Initializing validator [test_vp7]...done!
23:58:36.975 [chaincode] NewChaincodeSupport -> INFO 012 Chaincode support using peerAddress: 172.17.0.5:30303
23:58:36.975 [main] serve -> DEBU 013 Running as validating peer - making genesis block if needed
23:58:36.977 [db] createDBIfDBPathEmpty -> DEBU 014 Is db path [/var/hyperledger/production/db] empty [true]
23:58:36.977 [db] CreateDB -> DEBU 015 Creating DB at [/var/hyperledger/production/db]
23:58:36.994 [db] CreateDB -> DEBU 016 DB created at [/var/hyperledger/production/db]
23:58:37.018 [state] loadConfig -> INFO 017 Loading configurations...
23:58:37.018 [state] loadConfig -> INFO 018 Configurations loaded. stateImplName=[buckettree], stateImplConfigs=map[numBuckets:%!s(int=1000003) maxGroupingAtEachLevel:%!s(int=5) bucketCacheSize:%!s(int=100)], deltaHistorySize=[500]
23:58:37.018 [state] NewState -> INFO 019 Initializing state implementation [buckettree]
23:58:37.018 [buckettree] initConfig -> INFO 01a configs passed during initialization = map[string]interface {}{"bucketCacheSize":100, "numBuckets":1000003, "maxGroupingAtEachLevel":5}
23:58:37.018 [buckettree] initConfig -> INFO 01b Initializing bucket tree state implemetation with configurations &{maxGroupingAtEachLevel:5 lowestLevel:9 levelToNumBucketsMap:map[8:200001 3:65 4:321 1:3 9:1000003 2:13 0:1 7:40001 6:8001 5:1601] hashFunc:0xa59cf0}
23:58:37.018 [buckettree] newBucketCache -> INFO 01c Constructing bucket-cache with max bucket cache size = [100] MBs
23:58:37.018 [buckettree] loadAllBucketNodesFromDB -> INFO 01d Loaded buckets data in cache. Total buckets in DB = [0]. Total cache size:=0
23:58:37.018 [genesis] func1 -> INFO 01e Creating genesis block.
23:58:37.018 [genesis] loadConfigs -> INFO 01f Loading configurations...
23:58:37.018 [genesis] loadConfigs -> INFO 020 Configurations loaded: genesis=map[chaincodes:<nil>], mode=[], deploySystemChaincodeEnabled=[false]
23:58:37.019 [genesis] func1 -> INFO 021 No genesis block chaincodes defined.
23:58:37.019 [state] GetHash -> DEBU 022 Enter - GetHash()
23:58:37.019 [buckettree] ComputeCryptoHash -> DEBU 023 Enter - ComputeCryptoHash()
23:58:37.019 [buckettree] ComputeCryptoHash -> DEBU 024 Returing existing crypto-hash as recomputation not required
23:58:37.019 [state] GetHash -> DEBU 025 Exit - GetHash()
23:58:37.019 [indexes] addIndexDataForPersistence -> DEBU 026 Indexing block number [0] by hash = [46b9dd2b0ba88d13233b3feb743eeb243fcd52ea62b81b82b50c27646ed5762fd75dc4ddd8c0f200cb05019d67b592f6fc821c49479ab48640292eacb3b7c4be]
23:58:37.019 [state] AddChangesForPersistence -> DEBU 027 state.addChangesForPersistence()...start
23:58:37.019 [state] AddChangesForPersistence -> DEBU 028 Adding state-delta corresponding to block number[0]
23:58:37.019 [state] AddChangesForPersistence -> DEBU 029 Not deleting previous state-delta. Block number [0] is smaller than historyStateDeltaSize [500]
23:58:37.019 [state] AddChangesForPersistence -> DEBU 02a state.addChangesForPersistence()...finished
23:58:37.019 [ledger] resetForNextTxGroup -> DEBU 02b resetting ledger state for next transaction batch
23:58:37.019 [buckettree] ClearWorkingSet -> DEBU 02c Enter - ClearWorkingSet()
23:58:37.019 [genesis] 1 -> INFO 02d Adding 0 system chaincodes to the genesis block.
23:58:37.020 [main] serve -> DEBU 02e Running as validating peer - installing consensus
23:58:37.020 [consensus/statetransfer] Initiate -> DEBU 02f name:"vp3"  attempting to issue a state transfer request
23:58:37.020 [consensus/controller] NewConsenter -> INFO 030 Creating consensus plugin pbft
23:58:37.020 [consensus/obcpbft] restoreBlockNumber -> INFO 031 Sieve replica 3 restored blockNumber to 0
23:58:37.020 [consensus/statetransfer] VerifyAndRecoverBlockchain -> DEBU 032 name:"vp3"  validating existing blockchain, highest validated block is 0, valid through 0
23:58:37.020 [consensus/statetransfer] blockThread -> DEBU 033 name:"vp3"  has validated its blockchain to the genesis block
23:58:37.021 [consensus/statetransfer] stateThread -> DEBU 034 name:"vp3"  is initiating state transfer
23:58:37.021 [consensus/statetransfer] attemptStateTransfer -> DEBU 036 name:"vp3"  has no valid block hash to validate the blockchain with yet, waiting for a known valid block hash
23:58:37.021 [consensus/obcpbft] newPbftCore -> INFO 035 PBFT type = *obcpbft.obcSieve
23:58:37.021 [consensus/obcpbft] newPbftCore -> INFO 037 PBFT Max number of validating peers (N) = 4
23:58:37.021 [consensus/obcpbft] newPbftCore -> INFO 038 PBFT Max number of failing peers (f) = 1
23:58:37.021 [consensus/obcpbft] newPbftCore -> INFO 039 PBFT byzantine flag = false
23:58:37.021 [consensus/obcpbft] newPbftCore -> INFO 03a PBFT request timeout = 2s
23:58:37.021 [consensus/obcpbft] newPbftCore -> INFO 03b PBFT view change timeout = 2s
23:58:37.021 [consensus/obcpbft] newPbftCore -> INFO 03c PBFT Checkpoint period (K) = 10
23:58:37.021 [consensus/obcpbft] newPbftCore -> INFO 03d PBFT Log multiplier = 4
23:58:37.021 [consensus/obcpbft] newPbftCore -> INFO 03e PBFT log size (L) = 40
23:58:37.022 [consensus/obcpbft] stopTimer -> DEBU 03f Replica 3 stopping a running new view timer
23:58:37.022 [consensus/obcpbft] moveWatermarks -> DEBU 040 Replica 3 updated low watermark to 0
23:58:37.022 [consensus/obcpbft] restoreLastSeqNo -> INFO 041 Replica 3 restored lastExec: 0
23:58:37.022 [consensus/obcpbft] restoreState -> INFO 042 Replica 3 restored state: view: 0, seqNo: 0, pset: 0, qset: 0, reqs: 0, chkpts: 1
23:58:37.022 [consensus/obcpbft] main -> DEBU 043 Replica 3 service thread looping
23:58:37.023 [consensus/handler] 1 -> DEBU 044 Starting up message thread for consenter
23:58:37.023 [main] serve -> INFO 045 Starting peer with id=name:"vp3" , network id=dev, address=172.17.0.5:30303, discovery.rootnode=172.17.0.2:30303, validator=true
23:58:37.023 [rest] StartOpenchainRESTServer -> INFO 046 Initializing the REST service...
23:58:38.023 [peer] chatWithPeer -> DEBU 047 Initiating Chat with peer address: 172.17.0.2:30303
23:58:38.024 [peer] chatWithPeer -> DEBU 048 Established Chat with peer address: 172.17.0.2:30303
23:58:38.025 [peer] handleChat -> DEBU 049 Current context deadline = 0001-01-01 00:00:00 +0000 UTC, ok = false
23:58:38.025 [peer] SendMessage -> DEBU 04a Sending message to stream of type: DISC_HELLO
23:58:38.027 [consensus/util] RegisterChannel -> INFO 04b Registering connection from <nil>
23:58:38.085 [consensus/handler] HandleMessage -> DEBU 04c Did not handle message of type DISC_HELLO, passing on to next MessageHandler
23:58:38.085 [peer] HandleMessage -> DEBU 04d Handling Message of type: DISC_HELLO
23:58:38.085 [peer] beforeHello -> DEBU 04e Received DISC_HELLO, parsing out Peer identification
23:58:38.085 [peer] beforeHello -> DEBU 04f Received DISC_HELLO from endpoint=peerEndpoint:<ID:<name:"vp0" > address:"172.17.0.2:30303" type:VALIDATOR pkiID:"\231\023i\365t7\237Nu\231S\341\236v\255\014-v\336L\026p\335\370\310<T\024\250\332\341=" > blockchainInfo:<height:1 currentBlockHash:"F\271\335+\013\250\215\023#;?\353t>\353$?\315R\352b\270\033\202\265\014'dn\325v/\327]\304\335\330\300\362\000\313\005\001\235g\265\222\366\374\202\034IG\232\264\206@).\254\263\267\304\276" >
23:58:38.093 [peer] beforeHello -> DEBU 050 Verified signature for DISC_HELLO
23:58:38.093 [peer] RegisterHandler -> DEBU 051 registered handler with key: name:"vp0"
23:58:38.093 [peer] enterState -> DEBU 052 The Peer's bi-directional stream to ID:<name:"vp0" > address:"172.17.0.2:30303" type:VALIDATOR pkiID:"\231\023i\365t7\237Nu\231S\341\236v\255\014-v\336L\026p\335\370\310<T\024\250\332\341="  is established, from event DISC_HELLO
23:58:38.094 [peer] start -> DEBU 053 Starting Peer discovery service
23:58:39.167 [peer] handleChat -> DEBU 054 Current context deadline = 0001-01-01 00:00:00 +0000 UTC, ok = false
**23:58:39.168 [consensus/util] RegisterChannel -> WARN 055 Received duplicate connection from <nil>, switching to new connection**
23:58:39.168 [consensus/handler] HandleMessage -> DEBU 056 Did not handle message of type DISC_HELLO, passing on to next MessageHandler
23:58:39.168 [peer] HandleMessage -> DEBU 057 Handling Message of type: DISC_HELLO
23:58:39.168 [peer] beforeHello -> DEBU 058 Received DISC_HELLO, parsing out Peer identification
23:58:39.168 [peer] beforeHello -> DEBU 059 Received DISC_HELLO from endpoint=peerEndpoint:<ID:<name:"vp2" > address:"172.17.0.4:30303" type:VALIDATOR pkiID:"\244\254fXH!\303\031f\225\305T\216\234[y\267\036\000\333\324\210\362]P\234\206\3155\316\343K" > blockchainInfo:<height:1 currentBlockHash:"F\271\335+\013\250\215\023#;?\353t>\353$?\315R\352b\270\033\202\265\014'dn\325v/\327]\304\335\330\300\362\000\313\005\001\235g\265\222\366\374\202\034IG\232\264\206@).\254\263\267\304\276" >
23:58:39.253 [peer] beforeHello -> DEBU 05a Verified signature for DISC_HELLO
23:58:39.254 [peer] beforeHello -> DEBU 05b Received DISC_HELLO, sending back DISC_HELLO
23:58:39.254 [peer] SendMessage -> DEBU 05c Sending message to stream of type: DISC_HELLO
23:58:39.254 [peer] RegisterHandler -> DEBU 05d registered handler with key: name:"vp2"
23:58:39.255 [peer] enterState -> DEBU 05e The Peer's bi-directional stream to ID:<name:"vp2" > address:"172.17.0.4:30303" type:VALIDATOR pkiID:"\244\254fXH!\303\031f\225\305T\216\234[y\267\036\000\333\324\210\362]P\234\206\3155\316\343K"  is established, from event DISC_HELLO
23:58:39.258 [peer] start -> DEBU 05f Starting Peer discovery service
23:58:43.086 [consensus/handler] HandleMessage -> DEBU 060 Did not handle message of type DISC_GET_PEERS, passing on to next MessageHandler
23:58:43.086 [peer] HandleMessage -> DEBU 061 Handling Message of type: DISC_GET_PEERS
23:58:43.086 [peer] beforeGetPeers -> DEBU 062 Sending back DISC_PEERS
23:58:43.086 [peer] SendMessage -> DEBU 063 Sending message to stream of type: DISC_PEERS
23:58:43.094 [peer] SendMessage -> DEBU 064 Sending message to stream of type: DISC_GET_PEERS
23:58:43.095 [consensus/handler] HandleMessage -> DEBU 065 Did not handle message of type DISC_PEERS, passing on to next MessageHandler
23:58:43.095 [peer] HandleMessage -> DEBU 066 Handling Message of type: DISC_PEERS
23:58:43.095 [peer] beforePeers -> DEBU 067 Received DISC_PEERS, grabbing peers message
23:58:43.095 [peer] beforePeers -> DEBU 068 Received PeersMessage with Peers: peers:<ID:<name:"vp1" > address:"172.17.0.3:30303" type:VALIDATOR pkiID:"w\375^\203\265\344\375G'\242\274RA\025;\320-L4\372\355\322G`\357y\217\235\3547\270)" > peers:<ID:<name:"vp2" > address:"172.17.0.4:30303" type:VALIDATOR pkiID:"\244\254fXH!\303\031f\225\305T\216\234[y\267\036\000\333\324\210\362]P\234\206\3155\316\343K" > peers:<ID:<name:"vp3" > address:"172.17.0.5:30303" type:VALIDATOR pkiID:"9\\\227\0036t\312U\221\334\332:\327\017>\300\035\343\3234c\332d\356\255@\000\347>2\372\026" >
23:58:43.525 [peer] handleChat -> DEBU 069 Current context deadline = 0001-01-01 00:00:00 +0000 UTC, ok = false
**23:58:43.525 [consensus/util] RegisterChannel -> WARN 06a Received duplicate connection from <nil>, switching to new connection**
23:58:43.525 [consensus/handler] HandleMessage -> DEBU 06b Did not handle message of type DISC_HELLO, passing on to next MessageHandler
23:58:43.525 [peer] HandleMessage -> DEBU 06c Handling Message of type: DISC_HELLO
23:58:43.525 [peer] beforeHello -> DEBU 06d Received DISC_HELLO, parsing out Peer identification
23:58:43.526 [peer] beforeHello -> DEBU 06e Received DISC_HELLO from endpoint=peerEndpoint:<ID:<name:"vp1" > address:"172.17.0.3:30303" type:VALIDATOR pkiID:"w\375^\203\265\344\375G'\242\274RA\025;\320-L4\372\355\322G`\357y\217\235\3547\270)" > blockchainInfo:<height:1 currentBlockHash:"F\271\335+\013\250\215\023#;?\353t>\353$?\315R\352b\270\033\202\265\014'dn\325v/\327]\304\335\330\300\362\000\313\005\001\235g\265\222\366\374\202\034IG\232\264\206@).\254\263\267\304\276" >
23:58:43.540 [peer] beforeHello -> DEBU 06f Verified signature for DISC_HELLO
23:58:43.540 [peer] beforeHello -> DEBU 070 Received DISC_HELLO, sending back DISC_HELLO
23:58:43.540 [peer] SendMessage -> DEBU 071 Sending message to stream of type: DISC_HELLO
23:58:43.540 [peer] RegisterHandler -> DEBU 072 registered handler with key: name:"vp1"
23:58:43.540 [peer] enterState -> DEBU 073 The Peer's bi-directional stream to ID:<name:"vp1" > address:"172.17.0.3:30303" type:VALIDATOR pkiID:"w\375^\203\265\344\375G'\242\274RA\025;\320-L4\372\355\322G`\357y\217\235\3547\270)"  is established, from event DISC_HELLO
23:58:43.541 [peer] start -> DEBU 074 Starting Peer discovery service
23:58:44.096 [peer] chatWithPeer -> DEBU 075 Initiating Chat with peer address: 172.17.0.3:30303
23:58:44.097 [peer] chatWithPeer -> DEBU 076 Established Chat with peer address: 172.17.0.3:30303
23:58:44.097 [peer] handleChat -> DEBU 077 Current context deadline = 0001-01-01 00:00:00 +0000 UTC, ok = false
23:58:44.098 [peer] SendMessage -> DEBU 078 Sending message to stream of type: DISC_HELLO
**23:58:44.099 [consensus/util] RegisterChannel -> WARN 079 Received duplicate connection from <nil>, switching to new connection**
23:58:44.101 [consensus/handler] HandleMessage -> DEBU 07a Did not handle message of type DISC_HELLO, passing on to next MessageHandler
23:58:44.101 [peer] HandleMessage -> DEBU 07b Handling Message of type: DISC_HELLO
23:58:44.101 [peer] beforeHello -> DEBU 07c Received DISC_HELLO, parsing out Peer identification
23:58:44.101 [peer] beforeHello -> DEBU 07d Received DISC_HELLO from endpoint=peerEndpoint:<ID:<name:"vp1" > address:"172.17.0.3:30303" type:VALIDATOR pkiID:"w\375^\203\265\344\375G'\242\274RA\025;\320-L4\372\355\322G`\357y\217\235\3547\270)" > blockchainInfo:<height:1 currentBlockHash:"F\271\335+\013\250\215\023#;?\353t>\353$?\315R\352b\270\033\202\265\014'dn\325v/\327]\304\335\330\300\362\000\313\005\001\235g\265\222\366\374\202\034IG\232\264\206@).\254\263\267\304\276" >
23:58:44.102 [peer] beforeHello -> DEBU 07e Verified signature for DISC_HELLO
23:58:44.103 [peer] handleChat -> ERRO 07f Error handling message: Peer FSM failed while handling message (DISC_HELLO): current state: created, error: transition canceled with error: Error registering Handler: Duplicate Handler error: {name:"vp1"  172.17.0.3:30303 VALIDATOR w▒^▒▒▒▒G'▒▒RA;▒-L4▒▒▒G`▒y▒▒▒7▒)}
23:58:44.264 [peer] SendMessage -> DEBU 080 Sending message to stream of type: DISC_GET_PEERS
23:58:44.265 [consensus/handler] HandleMessage -> DEBU 081 Did not handle message of type DISC_PEERS, passing on to next MessageHandler
23:58:44.265 [peer] HandleMessage -> DEBU 082 Handling Message of type: DISC_PEERS
23:58:44.265 [peer] beforePeers -> DEBU 083 Received DISC_PEERS, grabbing peers message
23:58:44.265 [peer] beforePeers -> DEBU 084 Received PeersMessage with Peers: peers:<ID:<name:"vp0" > address:"172.17.0.2:30303" type:VALIDATOR pkiID:"\231\023i\365t7\237Nu\231S\341\236v\255\014-v\336L\026p\335\370\310<T\024\250\332\341=" > peers:<ID:<name:"vp1" > address:"172.17.0.3:30303" type:VALIDATOR pkiID:"w\375^\203\265\344\375G'\242\274RA\025;\320-L4\372\355\322G`\357y\217\235\3547\270)" > peers:<ID:<name:"vp3" > address:"172.17.0.5:30303" type:VALIDATOR pkiID:"9\\\227\0036t\312U\221\334\332:\327\017>\300\035\343\3234c\332d\356\255@\000\347>2\372\026" >
23:58:44.270 [consensus/handler] HandleMessage -> DEBU 085 Did not handle message of type DISC_GET_PEERS, passing on to next MessageHandler
23:58:44.270 [peer] HandleMessage -> DEBU 086 Handling Message of type: DISC_GET_PEERS
23:58:44.271 [peer] beforeGetPeers -> DEBU 087 Sending back DISC_PEERS
23:58:44.271 [peer] SendMessage -> DEBU 088 Sending message to stream of type: DISC_PEERS
23:58:48.086 [consensus/handler] HandleMessage -> DEBU 089 Did not handle message of type DISC_GET_PEERS, passing on to next MessageHandler
23:58:48.086 [peer] HandleMessage -> DEBU 08a Handling Message of type: DISC_GET_PEERS
23:58:48.086 [peer] beforeGetPeers -> DEBU 08b Sending back DISC_PEERS
23:58:48.086 [peer] SendMessage -> DEBU 08c Sending message to stream of type: DISC_PEERS
23:58:48.094 [peer] SendMessage -> DEBU 08d Sending message to stream of type: DISC_GET_PEERS
23:58:48.095 [consensus/handler] HandleMessage -> DEBU 08e Did not handle message of type DISC_PEERS, passing on to next MessageHandler
23:58:48.095 [peer] HandleMessage -> DEBU 08f Handling Message of type: DISC_PEERS
23:58:48.095 [peer] beforePeers -> DEBU 090 Received DISC_PEERS, grabbing peers message
23:58:48.095 [peer] beforePeers -> DEBU 091 Received PeersMessage with Peers: peers:<ID:<name:"vp1" > address:"172.17.0.3:30303" type:VALIDATOR pkiID:"w\375^\203\265\344\375G'\242\274RA\025;\320-L4\372\355\322G`\357y\217\235\3547\270)" > peers:<ID:<name:"vp2" > address:"172.17.0.4:30303" type:VALIDATOR pkiID:"\244\254fXH!\303\031f\225\305T\216\234[y\267\036\000\333\324\210\362]P\234\206\3155\316\343K" > peers:<ID:<name:"vp3" > address:"172.17.0.5:30303" type:VALIDATOR pkiID:"9\\\227\0036t\312U\221\334\332:\327\017>\300\035\343\3234c\332d\356\255@\000\347>2\372\026" >
23:58:48.545 [peer] SendMessage -> DEBU 092 Sending message to stream of type: DISC_GET_PEERS
23:58:48.549 [consensus/handler] HandleMessage -> DEBU 093 Did not handle message of type DISC_PEERS, passing on to next MessageHandler
23:58:48.549 [peer] HandleMessage -> DEBU 094 Handling Message of type: DISC_PEERS
23:58:48.550 [peer] beforePeers -> DEBU 095 Received DISC_PEERS, grabbing peers message
23:58:48.551 [peer] beforePeers -> DEBU 096 Received PeersMessage with Peers: peers:<ID:<name:"vp0" > address:"172.17.0.2:30303" type:VALIDATOR pkiID:"\231\023i\365t7\237Nu\231S\341\236v\255\014-v\336L\026p\335\370\310<T\024\250\332\341=" > peers:<ID:<name:"vp2" > address:"172.17.0.4:30303" type:VALIDATOR pkiID:"\244\254fXH!\303\031f\225\305T\216\234[y\267\036\000\333\324\210\362]P\234\206\3155\316\343K" > peers:<ID:<name:"vp3" > address:"172.17.0.5:30303" type:VALIDATOR pkiID:"9\\\227\0036t\312U\221\334\332:\327\017>\300\035\343\3234c\332d\356\255@\000\347>2\372\026" >
23:58:48.565 [consensus/handler] HandleMessage -> DEBU 097 Did not handle message of type DISC_GET_PEERS, passing on to next MessageHandler
23:58:48.565 [peer] HandleMessage -> DEBU 098 Handling Message of type: DISC_GET_PEERS
23:58:48.565 [peer] beforeGetPeers -> DEBU 099 Sending back DISC_PEERS
23:58:48.565 [peer] SendMessage -> DEBU 09a Sending message to stream of type: DISC_PEERS
23:58:49.265 [peer] SendMessage -> DEBU 09b Sending message to stream of type: DISC_GET_PEERS
23:58:49.265 [consensus/handler] HandleMessage -> DEBU 09c Did not handle message of type DISC_PEERS, passing on to next MessageHandler
23:58:49.265 [peer] HandleMessage -> DEBU 09d Handling Message of type: DISC_PEERS
23:58:49.265 [peer] beforePeers -> DEBU 09e Received DISC_PEERS, grabbing peers message
23:58:49.265 [peer] beforePeers -> DEBU 09f Received PeersMessage with Peers: peers:<ID:<name:"vp0" > address:"172.17.0.2:30303" type:VALIDATOR pkiID:"\231\023i\365t7\237Nu\231S\341\236v\255\014-v\336L\026p\335\370\310<T\024\250\332\341=" > peers:<ID:<name:"vp1" > address:"172.17.0.3:30303" type:VALIDATOR pkiID:"w\375^\203\265\344\375G'\242\274RA\025;\320-L4\372\355\322G`\357y\217\235\3547\270)" > peers:<ID:<name:"vp3" > address:"172.17.0.5:30303" type:VALIDATOR pkiID:"9\\\227\0036t\312U\221\334\332:\327\017>\300\035\343\3234c\332d\356\255@\000\347>2\372\026" >
23:58:49.271 [consensus/handler] HandleMessage -> DEBU 0a0 Did not handle message of type DISC_GET_PEERS, passing on to next MessageHandler
23:58:49.271 [peer] HandleMessage -> DEBU 0a1 Handling Message of type: DISC_GET_PEERS
23:58:49.271 [peer] beforeGetPeers -> DEBU 0a2 Sending back DISC_PEERS
23:58:49.271 [peer] SendMessage -> DEBU 0a3 Sending message to stream of type: DISC_PEERS
23:58:53.086 [consensus/handler] HandleMessage -> DEBU 0a4 Did not handle message of type DISC_GET_PEERS, passing on to next MessageHandler
23:58:53.086 [peer] HandleMessage -> DEBU 0a5 Handling Message of type: DISC_GET_PEERS
23:58:53.086 [peer] beforeGetPeers -> DEBU 0a6 Sending back DISC_PEERS
23:58:53.086 [peer] SendMessage -> DEBU 0a7 Sending message to stream of type: DISC_PEERS
23:58:53.094 [peer] SendMessage -> DEBU 0a8 Sending message to stream of type: DISC_GET_PEERS
23:58:53.095 [consensus/handler] HandleMessage -> DEBU 0a9 Did not handle message of type DISC_PEERS, passing on to next MessageHandler
23:58:53.095 [peer] HandleMessage -> DEBU 0aa Handling Message of type: DISC_PEERS
23:58:53.095 [peer] beforePeers -> DEBU 0ab Received DISC_PEERS, grabbing peers message
23:58:53.095 [peer] beforePeers -> DEBU 0ac Received PeersMessage with Peers: peers:<ID:<name:"vp1" > address:"172.17.0.3:30303" type:VALIDATOR pkiID:"w\375^\203\265\344\375G'\242\274RA\025;\320-L4\372\355\322G`\357y\217\235\3547\270)" > peers:<ID:<name:"vp2" > address:"172.17.0.4:30303" type:VALIDATOR pkiID:"\244\254fXH!\303\031f\225\305T\216\234[y\267\036\000\333\324\210\362]P\234\206\3155\316\343K" > peers:<ID:<name:"vp3" > address:"172.17.0.5:30303" type:VALIDATOR pkiID:"9\\\227\0036t\312U\221\334\332:\327\017>\300\035\343\3234c\332d\356\255@\000\347>2\372\026" >
23:58:53.545 [peer] SendMessage -> DEBU 0ad Sending message to stream of type: DISC_GET_PEERS
23:58:53.547 [consensus/handler] HandleMessage -> DEBU 0ae Did not handle message of type DISC_PEERS, passing on to next MessageHandler
23:58:53.547 [peer] HandleMessage -> DEBU 0af Handling Message of type: DISC_PEERS
23:58:53.547 [peer] beforePeers -> DEBU 0b0 Received DISC_PEERS, grabbing peers message
23:58:53.547 [peer] beforePeers -> DEBU 0b1 Received PeersMessage with Peers: peers:<ID:<name:"vp0" > address:"172.17.0.2:30303" type:VALIDATOR pkiID:"\231\023i\365t7\237Nu\231S\341\236v\255\014-v\336L\026p\335\370\310<T\024\250\332\341=" > peers:<ID:<name:"vp2" > address:"172.17.0.4:30303" type:VALIDATOR pkiID:"\244\254fXH!\303\031f\225\305T\216\234[y\267\036\000\333\324\210\362]P\234\206\3155\316\343K" > peers:<ID:<name:"vp3" > address:"172.17.0.5:30303" type:VALIDATOR pkiID:"9\\\227\0036t\312U\221\334\332:\327\017>\300\035\343\3234c\332d\356\255@\000\347>2\372\026" >
23:58:53.564 [consensus/handler] HandleMessage -> DEBU 0b2 Did not handle message of type DISC_GET_PEERS, passing on to next MessageHandler
23:58:53.565 [peer] HandleMessage -> DEBU 0b3 Handling Message of type: DISC_GET_PEERS
23:58:53.565 [peer] beforeGetPeers -> DEBU 0b4 Sending back DISC_PEERS
23:58:53.565 [peer] SendMessage -> DEBU 0b5 Sending message to stream of type: DISC_PEERS
23:58:54.265 [peer] SendMessage -> DEBU 0b6 Sending message to stream of type: DISC_GET_PEERS
23:58:54.269 [consensus/handler] HandleMessage -> DEBU 0b7 Did not handle message of type DISC_PEERS, passing on to next MessageHandler
23:58:54.269 [peer] HandleMessage -> DEBU 0b8 Handling Message of type: DISC_PEERS
23:58:54.270 [peer] beforePeers -> DEBU 0b9 Received DISC_PEERS, grabbing peers message
23:58:54.270 [peer] beforePeers -> DEBU 0ba Received PeersMessage with Peers: peers:<ID:<name:"vp1" > address:"172.17.0.3:30303" type:VALIDATOR pkiID:"w\375^\203\265\344\375G'\242\274RA\025;\320-L4\372\355\322G`\357y\217\235\3547\270)" > peers:<ID:<name:"vp3" > address:"172.17.0.5:30303" type:VALIDATOR pkiID:"9\\\227\0036t\312U\221\334\332:\327\017>\300\035\343\3234c\332d\356\255@\000\347>2\372\026" > peers:<ID:<name:"vp0" > address:"172.17.0.2:30303" type:VALIDATOR pkiID:"\231\023i\365t7\237Nu\231S\341\236v\255\014-v\336L\026p\335\370\310<T\024\250\332\341=" >
23:58:54.271 [consensus/handler] HandleMessage -> DEBU 0bb Did not handle message of type DISC_GET_PEERS, passing on to next MessageHandler
23:58:54.272 [peer] HandleMessage -> DEBU 0bc Handling Message of type: DISC_GET_PEERS
23:58:54.272 [peer] beforeGetPeers -> DEBU 0bd Sending back DISC_PEERS
23:58:54.273 [peer] SendMessage -> DEBU 0be Sending message to stream of type: DISC_PEERS
23:58:58.086 [consensus/handler] HandleMessage -> DEBU 0bf Did not handle message of type DISC_GET_PEERS, passing on to next MessageHandler
23:58:58.086 [peer] HandleMessage -> DEBU 0c0 Handling Message of type: DISC_GET_PEERS
23:58:58.086 [peer] beforeGetPeers -> DEBU 0c1 Sending back DISC_PEERS
23:58:58.086 [peer] SendMessage -> DEBU 0c2 Sending message to stream of type: DISC_PEERS
23:58:58.094 [peer] SendMessage -> DEBU 0c3 Sending message to stream of type: DISC_GET_PEERS
23:58:58.095 [consensus/handler] HandleMessage -> DEBU 0c4 Did not handle message of type DISC_PEERS, passing on to next MessageHandler
23:58:58.095 [peer] HandleMessage -> DEBU 0c5 Handling Message of type: DISC_PEERS
23:58:58.095 [peer] beforePeers -> DEBU 0c6 Received DISC_PEERS, grabbing peers message
23:58:58.095 [peer] beforePeers -> DEBU 0c7 Received PeersMessage with Peers: peers:<ID:<name:"vp1" > address:"172.17.0.3:30303" type:VALIDATOR pkiID:"w\375^\203\265\344\375G'\242\274RA\025;\320-L4\372\355\322G`\357y\217\235\3547\270)" > peers:<ID:<name:"vp2" > address:"172.17.0.4:30303" type:VALIDATOR pkiID:"\244\254fXH!\303\031f\225\305T\216\234[y\267\036\000\333\324\210\362]P\234\206\3155\316\343K" > peers:<ID:<name:"vp3" > address:"172.17.0.5:30303" type:VALIDATOR pkiID:"9\\\227\0036t\312U\221\334\332:\327\017>\300\035\343\3234c\332d\356\255@\000\347>2\372\026" >
23:58:58.546 [peer] SendMessage -> DEBU 0c8 Sending message to stream of type: DISC_GET_PEERS
23:58:58.546 [consensus/handler] HandleMessage -> DEBU 0c9 Did not handle message of type DISC_PEERS, passing on to next MessageHandler
23:58:58.546 [peer] HandleMessage -> DEBU 0ca Handling Message of type: DISC_PEERS
23:58:58.546 [peer] beforePeers -> DEBU 0cb Received DISC_PEERS, grabbing peers message
23:58:58.546 [peer] beforePeers -> DEBU 0cc Received PeersMessage with Peers: peers:<ID:<name:"vp0" > address:"172.17.0.2:30303" type:VALIDATOR pkiID:"\231\023i\365t7\237Nu\231S\341\236v\255\014-v\336L\026p\335\370\310<T\024\250\332\341=" > peers:<ID:<name:"vp2" > address:"172.17.0.4:30303" type:VALIDATOR pkiID:"\244\254fXH!\303\031f\225\305T\216\234[y\267\036\000\333\324\210\362]P\234\206\3155\316\343K" > peers:<ID:<name:"vp3" > address:"172.17.0.5:30303" type:VALIDATOR pkiID:"9\\\227\0036t\312U\221\334\332:\327\017>\300\035\343\3234c\332d\356\255@\000\347>2\372\026" >
23:58:58.565 [consensus/handler] HandleMessage -> DEBU 0cd Did not handle message of type DISC_GET_PEERS, passing on to next MessageHandler
23:58:58.565 [peer] HandleMessage -> DEBU 0ce Handling Message of type: DISC_GET_PEERS
23:58:58.565 [peer] beforeGetPeers -> DEBU 0cf Sending back DISC_PEERS
23:58:58.565 [peer] SendMessage -> DEBU 0d0 Sending message to stream of type: DISC_PEERS
23:58:59.266 [peer] SendMessage -> DEBU 0d1 Sending message to stream of type: DISC_GET_PEERS
23:58:59.266 [consensus/handler] HandleMessage -> DEBU 0d2 Did not handle message of type DISC_PEERS, passing on to next MessageHandler
23:58:59.267 [peer] HandleMessage -> DEBU 0d3 Handling Message of type: DISC_PEERS
23:58:59.267 [peer] beforePeers -> DEBU 0d4 Received DISC_PEERS, grabbing peers message
23:58:59.267 [peer] beforePeers -> DEBU 0d5 Received PeersMessage with Peers: peers:<ID:<name:"vp0" > address:"172.17.0.2:30303" type:VALIDATOR pkiID:"\231\023i\365t7\237Nu\231S\341\236v\255\014-v\336L\026p\335\370\310<T\024\250\332\341=" > peers:<ID:<name:"vp1" > address:"172.17.0.3:30303" type:VALIDATOR pkiID:"w\375^\203\265\344\375G'\242\274RA\025;\320-L4\372\355\322G`\357y\217\235\3547\270)" > peers:<ID:<name:"vp3" > address:"172.17.0.5:30303" type:VALIDATOR pkiID:"9\\\227\0036t\312U\221\334\332:\327\017>\300\035\343\3234c\332d\356\255@\000\347>2\372\026" >
23:58:59.271 [consensus/handler] HandleMessage -> DEBU 0d6 Did not handle message of type DISC_GET_PEERS, passing on to next MessageHandler
23:58:59.272 [peer] HandleMessage -> DEBU 0d7 Handling Message of type: DISC_GET_PEERS
23:58:59.272 [peer] beforeGetPeers -> DEBU 0d8 Sending back DISC_PEERS
23:58:59.272 [peer] SendMessage -> DEBU 0d9 Sending message to stream of type: DISC_PEERS
mastersingh24 commented 8 years ago

is this only with pbft sieve?

RicHernandez2 commented 8 years ago

It repros in Classic as well, to aid in reproducing the issue, this is how I'm calling my 4 VPs:

docker run --rm -it -e CORE_VM_ENDPOINT=http://172.17.0.1:4243 -e CORE_PEER_ID=vp0 -e CORE_PEER_ADDRESSAUTODETECT=true -e CORE_PEER_PKI_ECA_PADDR=172.17.0.1:50051 -e CORE_PEER_PKI_TCA_PADDR=172.17.0.1:50051 -e CORE_PEER_PKI_TLSCA_PADDR=172.17.0.1:50051 -v /opt/logs/vp0:/go -p 5000:5000 hyperledger-peer peer peer
docker run --rm -it -e CORE_VM_ENDPOINT=http://172.17.0.1:4243 -e CORE_PEER_ID=vp1 -e CORE_PEER_ADDRESSAUTODETECT=true -e CORE_PEER_DISCOVERY_ROOTNODE=172.17.0.2:30303 -e CORE_PEER_PKI_ECA_PADDR=172.17.0.1:50051 -e CORE_PEER_PKI_TCA_PADDR=172.17.0.1:50051 -e CORE_PEER_PKI_TLSCA_PADDR=172.17.0.1:50051 -e CORE_SECURITY_ENROLLID=test_vp5 -e CORE_SECURITY_ENROLLSECRET=FfdvDkAdY81P -v /opt/logs/vp1:/go hyperledger-peer peer peer
docker run --rm -it -e CORE_VM_ENDPOINT=http://172.17.0.1:4243 -e CORE_PEER_ID=vp2 -e CORE_PEER_ADDRESSAUTODETECT=true -e CORE_PEER_DISCOVERY_ROOTNODE=172.17.0.2:30303 -e CORE_PEER_PKI_ECA_PADDR=172.17.0.1:50051 -e CORE_PEER_PKI_TCA_PADDR=172.17.0.1:50051 -e CORE_PEER_PKI_TLSCA_PADDR=172.17.0.1:50051 -e CORE_SECURITY_ENROLLID=test_vp6 -e CORE_SECURITY_ENROLLSECRET=QiXJgHyV4t7A -v /opt/logs/vp2:/go hyperledger-peer peer peer
docker run --rm -it -e CORE_VM_ENDPOINT=http://172.17.0.1:4243 -e CORE_PEER_ID=vp3 -e CORE_PEER_ADDRESSAUTODETECT=true -e CORE_PEER_DISCOVERY_ROOTNODE=172.17.0.2:30303 -e CORE_PEER_PKI_ECA_PADDR=172.17.0.1:50051 -e CORE_PEER_PKI_TCA_PADDR=172.17.0.1:50051 -e CORE_PEER_PKI_TLSCA_PADDR=172.17.0.1:50051 -e CORE_SECURITY_ENROLLID=test_vp7 -e CORE_SECURITY_ENROLLSECRET=twoKZouEyLyB -v /opt/logs/vp3:/go hyperledger-peer peer peer
RicHernandez2 commented 8 years ago

Here's a screenshot, I got a 100% repro with it.

sieve warn

jyellick commented 8 years ago

@jeffgarratt It seems that handler.peerHandler.To() is returning nil in some cases, any theory as to why this could be happening?

Edit: Actually, my guess is that because the HELLO has not gone through yet, this is always going to be nil, how would you suggest that we detect once a peer has negotiated its peer ID?

RicHernandez2 commented 8 years ago

Here's the deploy and chaincode I'm running if it helps you to repro:

{
  "jsonrpc": "2.0",
  "method": "deploy",
  "params": {
    "type": 1,
    "chaincodeID":{
        "path":"github.com/hyperledger/fabric/examples/chaincode/go/ndt"
    },
    "ctorMsg": {
        "function":"init",
        "args":["a", "1000", "b", "2000"]
    },
    "secureContext": "lukas"
  },
  "id": 1
}

nond2.zip