Uploaded image for project: 'Fabric'
  1. Fabric
  2. FAB-707

disconnected Peer can't recover from lost connection, then start sending view change requests

    XMLWordPrintable

Details

    • Bug
    • Status: Closed
    • High
    • Resolution: Done
    • v0.6
    • WON'T FIX
    • fabric-orderer
    • nodes are deployed on different machines

      but you can also simulate this behavior in BDD after setting K to 10

    Description

      v0.6 code base

      way to reproduce:

      set K=10

      Deploy chaincode
      Stop vp3
      Send vp0 any number of transactions (I have tried 3 and 50+, the latter will move it past peer's high watermark)
      Start vp3
      (at this point, if you query, vp3 will not return updated world state)
      Stop vp3
      Send vp0 a few more transactions
      Start vp3
      query/invoke world state a few times
      (at some point the vp3 peer will notice it is behind, and then it will stop broadcasting transactions until the network progresses to H, but before that it will start thinking the primary is bad and start sending view change requests to other peers. However this view change request will never stop, since other peers will think the view is ok and will not also send view change requests)

      The biggest problem is once a node experience network failures and missed a tx or 2, then it will enter un-ending loop of view change requests even after restarting the node (in most cases, since this status is persisted, but there are cases the status don't get persisted so restart would work — likely another bug).

      VP3 Log:

      2016-10-13T06:40:13.355382628Z 14:40:13.354 [rest] ProcessChaincode -> INFO 02c REST processing chaincode request...
      2016-10-13T06:40:13.356770119Z 14:40:13.356 [rest] processChaincodeInvokeOrQuery -> INFO 02d REST query chaincode...
      2016-10-13T06:40:13.358234467Z 14:40:13.357 [rest] processChaincodeInvokeOrQuery -> INFO 02e Local user 'WebAppAdmin' is already logged in. Retrieving login token.
      2016-10-13T06:40:13.359274523Z 14:40:13.359 [devops] invokeOrQuery -> INFO 02f Transaction ID: a89051f6-ca8c-4209-893c-dfc7feea132d
      2016-10-13T06:40:13.359763704Z 14:40:13.359 [crypto] InitClient -> INFO 030 Initializing client [WebAppAdmin]...
      2016-10-13T06:40:13.531133086Z 14:40:13.530 [crypto] InitClient -> INFO 031 Initializing client [WebAppAdmin]...done!
      2016-10-13T06:40:19.039016928Z 14:40:19.038 [crypto] closeClientInternal -> INFO 032 Closing client [WebAppAdmin]...
      2016-10-13T06:40:19.101091198Z 14:40:19.100 [rest] processChaincodeInvokeOrQuery -> INFO 033 Successfully queried chaincode: 10000000
      2016-10-13T06:40:19.102617413Z 14:40:19.101 [rest] ProcessChaincode -> INFO 034 REST successfully query chaincode: {"jsonrpc":"2.0","result":

      {"status":"OK","message":"10000000"}

      ,"id":5}
      2016-10-13T06:40:38.283587179Z 14:40:38.279 [rest] ProcessChaincode -> INFO 035 REST processing chaincode request...
      2016-10-13T06:40:38.283647199Z 14:40:38.279 [rest] processChaincodeInvokeOrQuery -> INFO 036 REST invoke chaincode...
      2016-10-13T06:40:38.283660184Z 14:40:38.279 [rest] processChaincodeInvokeOrQuery -> INFO 037 Local user 'WebAppAdmin' is already logged in. Retrieving login token.
      2016-10-13T06:40:38.283669160Z 14:40:38.280 [devops] invokeOrQuery -> INFO 038 Transaction ID: 3deb8664-2ea1-4e07-895c-b838f61c9daf
      2016-10-13T06:40:38.283676533Z 14:40:38.280 [crypto] InitClient -> INFO 039 Initializing client [WebAppAdmin]...
      2016-10-13T06:40:38.449260250Z 14:40:38.449 [crypto] InitClient -> INFO 03a Initializing client [WebAppAdmin]...done!
      2016-10-13T06:40:38.450076225Z 14:40:38.449 [crypto] closeClientInternal -> INFO 03b Closing client [WebAppAdmin]...
      2016-10-13T06:40:38.514754101Z 14:40:38.514 [rest] processChaincodeInvokeOrQuery -> INFO 03c Successfully submitted invoke transaction with txid (3deb8664-2ea1-4e07-895c-b838f61c9daf)
      2016-10-13T06:40:38.515365413Z 14:40:38.514 [rest] ProcessChaincode -> INFO 03d REST successfully submitted invoke transaction: {"jsonrpc":"2.0","result":

      {"status":"OK","message":"3deb8664-2ea1-4e07-895c-b838f61c9daf"}

      ,"id":1}
      2016-10-13T06:40:48.461565468Z 14:40:48.460 [consensus/pbft] ProcessEvent -> INFO 03e Replica 3 view change timer expired, sending view change: Batch outstanding requests
      2016-10-13T06:40:48.463446964Z 14:40:48.463 [consensus/pbft] sendViewChange -> INFO 03f Replica 3 sending view-change, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:48.465177019Z 14:40:48.464 [consensus/pbft] recvViewChange -> INFO 040 Replica 3 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:50.465953533Z 14:40:50.465 [consensus/pbft] sendViewChange -> INFO 041 Replica 3 sending view-change, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:50.467386532Z 14:40:50.466 [consensus/pbft] recvViewChange -> INFO 042 Replica 3 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:50.468601501Z 14:40:50.468 [consensus/pbft] recvViewChange -> WARN 043 Replica 3 already has a view change message for view 1 from replica 3
      2016-10-13T06:40:52.469097537Z 14:40:52.468 [consensus/pbft] sendViewChange -> INFO 044 Replica 3 sending view-change, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:52.472291299Z 14:40:52.471 [consensus/pbft] recvViewChange -> INFO 045 Replica 3 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:52.475499721Z 14:40:52.475 [consensus/pbft] recvViewChange -> WARN 046 Replica 3 already has a view change message for view 1 from replica 3
      2016-10-13T06:40:54.473388350Z 14:40:54.472 [consensus/pbft] sendViewChange -> INFO 047 Replica 3 sending view-change, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:54.475203585Z 14:40:54.474 [consensus/pbft] recvViewChange -> INFO 048 Replica 3 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:54.477673544Z 14:40:54.477 [consensus/pbft] recvViewChange -> WARN 049 Replica 3 already has a view change message for view 1 from replica 3
      2016-10-13T06:40:56.479023414Z 14:40:56.477 [consensus/pbft] sendViewChange -> INFO 04a Replica 3 sending view-change, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:56.479108449Z 14:40:56.477 [consensus/pbft] recvViewChange -> INFO 04b Replica 3 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:56.479122208Z 14:40:56.478 [consensus/pbft] recvViewChange -> WARN 04c Replica 3 already has a view change message for view 1 from replica 3
      2016-10-13T06:40:58.479865467Z 14:40:58.479 [consensus/pbft] sendViewChange -> INFO 04d Replica 3 sending view-change, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:58.480836852Z 14:40:58.480 [consensus/pbft] recvViewChange -> INFO 04e Replica 3 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:58.482556746Z 14:40:58.482 [consensus/pbft] recvViewChange -> WARN 04f Replica 3 already has a view change message for view 1 from replica 3
      2016-10-13T06:41:00.484739101Z 14:41:00.483 [consensus/pbft] sendViewChange -> INFO 050 Replica 3 sending view-change, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:41:00.486727018Z 14:41:00.486 [consensus/pbft] recvViewChange -> INFO 051 Replica 3 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:41:00.488710055Z 14:41:00.488 [consensus/pbft] recvViewChange -> WARN 052 Replica 3 already has a view change message for view 1 from replica 3
      2016-10-13T06:41:02.488723335Z 14:41:02.488 [consensus/pbft] sendViewChange -> INFO 053 Replica 3 sending view-change, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:41:02.489028215Z 14:41:02.488 [consensus/pbft] recvViewChange -> INFO 054 Replica 3 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:41:02.490053942Z 14:41:02.489 [consensus/pbft] recvViewChange -> WARN 055 Replica 3 already has a view change message for view 1 from replica 3

      VP0 Log

      2016-10-13T06:21:51.229828941Z 14:21:51.226 [rest] ProcessChaincode -> INFO 0a2 REST processing chaincode request...
      2016-10-13T06:21:51.229992941Z 14:21:51.226 [rest] processChaincodeInvokeOrQuery -> INFO 0a3 REST query chaincode...
      2016-10-13T06:21:51.230271921Z 14:21:51.227 [rest] processChaincodeInvokeOrQuery -> INFO 0a4 Local user 'lukas' is already logged in. Retrieving login token.
      2016-10-13T06:21:51.230306918Z 14:21:51.228 [devops] invokeOrQuery -> INFO 0a5 Transaction ID: 4063c51e-f7ba-474b-879f-5b8b244c54f4
      2016-10-13T06:21:51.230332021Z 14:21:51.228 [crypto] InitClient -> INFO 0a6 Initializing client [lukas]...
      2016-10-13T06:21:51.584828001Z 14:21:51.584 [crypto] InitClient -> INFO 0a7 Initializing client [lukas]...done!
      2016-10-13T06:21:51.592824019Z 14:21:51.592 [crypto] closeClientInternal -> INFO 0a8 Closing client [lukas]...
      2016-10-13T06:21:51.747391011Z 14:21:51.746 [rest] processChaincodeInvokeOrQuery -> INFO 0a9 Successfully queried chaincode: 9999995
      2016-10-13T06:21:51.747541748Z 14:21:51.747 [rest] ProcessChaincode -> INFO 0aa REST successfully query chaincode: {"jsonrpc":"2.0","result":

      {"status":"OK","message":"9999995"}

      ,"id":5}
      2016-10-13T06:37:21.468108942Z 14:37:21.467 [peer] handleChat -> ERRO 0ab Error during Chat, stopping handler: stream error: code = 1 desc = "context canceled"
      2016-10-13T06:37:21.471550664Z 14:37:21.469 [peer] handleChat -> ERRO 0ac Error during Chat, stopping handler: stream error: code = 1 desc = "context canceled"
      2016-10-13T06:37:21.872733785Z 14:37:21.842 [peer] ensureConnected -> WARN 0ad Touch service indicates dropped connections, attempting to reconnect...
      2016-10-13T06:37:22.845546290Z 2016/10/13 14:37:22 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:24.462145845Z 2016/10/13 14:37:24 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:24.847708157Z 14:37:24.844 [peer] chatWithPeer -> ERRO 0ae Error creating connection to peer address 10.20.26.81:7051: grpc: timed out when dialing
      2016-10-13T06:37:24.847823427Z 2016/10/13 14:37:24 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:27.842679082Z 14:37:27.841 [peer] ensureConnected -> WARN 0af Touch service indicates dropped connections, attempting to reconnect...
      2016-10-13T06:37:28.843671599Z 2016/10/13 14:37:28 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:30.225842377Z 2016/10/13 14:37:30 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:30.843118277Z 2016/10/13 14:37:30 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:30.843239157Z 14:37:30.842 [peer] chatWithPeer -> ERRO 0b0 Error creating connection to peer address 10.20.26.81:7051: grpc: timed out when dialing
      2016-10-13T06:37:31.279993217Z 14:37:31.279 [rest] ProcessChaincode -> INFO 0b1 REST processing chaincode request...
      2016-10-13T06:37:31.281168752Z 14:37:31.280 [rest] processChaincodeInvokeOrQuery -> INFO 0b2 REST invoke chaincode...
      2016-10-13T06:37:31.282310162Z 14:37:31.281 [rest] processChaincodeInvokeOrQuery -> INFO 0b3 Local user 'lukas' is already logged in. Retrieving login token.
      2016-10-13T06:37:31.282758145Z 14:37:31.282 [devops] invokeOrQuery -> INFO 0b4 Transaction ID: 70dbcb7e-3143-4e4b-aefc-634ced7cb29f
      2016-10-13T06:37:31.283296499Z 14:37:31.282 [crypto] InitClient -> INFO 0b5 Initializing client [lukas]...
      2016-10-13T06:37:31.660180347Z 14:37:31.659 [crypto] InitClient -> INFO 0b6 Initializing client [lukas]...done!
      2016-10-13T06:37:31.661402134Z 14:37:31.661 [crypto] closeClientInternal -> INFO 0b7 Closing client [lukas]...
      2016-10-13T06:37:31.662340520Z 14:37:31.662 [consensus/pbft] sendBatch -> INFO 0b8 Creating batch with 1 requests
      2016-10-13T06:37:31.667011406Z 14:37:31.666 [consensus/pbft] executeOne -> INFO 0b9 Replica 0 executing/committing request batch for view=0/seqNo=7 and digest 6ta8XRrX4SxaIOdc2iZpt6zMeRCPLml5nGRdVbH+FBHGEkjV9/UMGoiO1gUSiwONBgmT4kVrtG2yTvtNLDZlvQ==
      2016-10-13T06:37:31.684015940Z 14:37:31.683 [consensus/pbft] execDoneSync -> INFO 0ba Replica 0 finished execution 7, trying next
      2016-10-13T06:37:31.818382756Z 14:37:31.817 [rest] processChaincodeInvokeOrQuery -> INFO 0bb Successfully submitted invoke transaction with txid (70dbcb7e-3143-4e4b-aefc-634ced7cb29f)
      2016-10-13T06:37:31.819173365Z 14:37:31.818 [rest] ProcessChaincode -> INFO 0bc REST successfully submitted invoke transaction: {"jsonrpc":"2.0","result":

      {"status":"OK","message":"70dbcb7e-3143-4e4b-aefc-634ced7cb29f"}

      ,"id":1}
      2016-10-13T06:37:32.337394525Z 14:37:32.337 [rest] ProcessChaincode -> INFO 0bd REST processing chaincode request...
      2016-10-13T06:37:32.337686237Z 14:37:32.337 [rest] processChaincodeInvokeOrQuery -> INFO 0be REST invoke chaincode...
      2016-10-13T06:37:32.338081352Z 14:37:32.337 [rest] processChaincodeInvokeOrQuery -> INFO 0bf Local user 'lukas' is already logged in. Retrieving login token.
      2016-10-13T06:37:32.338910705Z 14:37:32.338 [devops] invokeOrQuery -> INFO 0c0 Transaction ID: b9897c64-e1a9-429b-98c3-31387c3067ac
      2016-10-13T06:37:32.338951454Z 14:37:32.338 [crypto] InitClient -> INFO 0c1 Initializing client [lukas]...
      2016-10-13T06:37:32.602482645Z 14:37:32.602 [crypto] InitClient -> INFO 0c2 Initializing client [lukas]...done!
      2016-10-13T06:37:32.603257787Z 14:37:32.602 [crypto] closeClientInternal -> INFO 0c3 Closing client [lukas]...
      2016-10-13T06:37:32.604894548Z 14:37:32.603 [consensus/pbft] sendBatch -> INFO 0c4 Creating batch with 1 requests
      2016-10-13T06:37:32.617868208Z 14:37:32.617 [consensus/pbft] executeOne -> INFO 0c5 Replica 0 executing/committing request batch for view=0/seqNo=8 and digest KlPFqVCzGcVhIVP4cIsNC33leUgtvd6d7lE0fimGg1Ppc6KUgfsJWZcKSSbz87COE7TmyNiawm7T8B5r1KomRg==
      2016-10-13T06:37:32.624340340Z 14:37:32.624 [consensus/pbft] execDoneSync -> INFO 0c6 Replica 0 finished execution 8, trying next
      2016-10-13T06:37:32.711900019Z 14:37:32.711 [rest] processChaincodeInvokeOrQuery -> INFO 0c7 Successfully submitted invoke transaction with txid (b9897c64-e1a9-429b-98c3-31387c3067ac)
      2016-10-13T06:37:32.713054088Z 14:37:32.712 [rest] ProcessChaincode -> INFO 0c8 REST successfully submitted invoke transaction: {"jsonrpc":"2.0","result":

      {"status":"OK","message":"b9897c64-e1a9-429b-98c3-31387c3067ac"}

      ,"id":1}
      2016-10-13T06:37:33.230197104Z 14:37:33.229 [rest] ProcessChaincode -> INFO 0c9 REST processing chaincode request...
      2016-10-13T06:37:33.231237410Z 14:37:33.230 [rest] processChaincodeInvokeOrQuery -> INFO 0ca REST invoke chaincode...
      2016-10-13T06:37:33.232032614Z 14:37:33.231 [rest] processChaincodeInvokeOrQuery -> INFO 0cb Local user 'lukas' is already logged in. Retrieving login token.
      2016-10-13T06:37:33.232570021Z 14:37:33.232 [devops] invokeOrQuery -> INFO 0cc Transaction ID: 4f010a3f-c78d-4e5c-b590-c60b601615a3
      2016-10-13T06:37:33.233029088Z 14:37:33.232 [crypto] InitClient -> INFO 0cd Initializing client [lukas]...
      2016-10-13T06:37:33.461031752Z 14:37:33.460 [crypto] InitClient -> INFO 0ce Initializing client [lukas]...done!
      2016-10-13T06:37:33.461930764Z 14:37:33.461 [crypto] closeClientInternal -> INFO 0cf Closing client [lukas]...
      2016-10-13T06:37:33.463469641Z 14:37:33.463 [consensus/pbft] sendBatch -> INFO 0d0 Creating batch with 1 requests
      2016-10-13T06:37:33.467505766Z 14:37:33.467 [consensus/pbft] executeOne -> INFO 0d1 Replica 0 executing/committing request batch for view=0/seqNo=9 and digest nMZ7Ji6LoZOfbspMg++/xijd7+kza5J0mFMCj4aMva4VyAbtegnZ5iHE9de3F9QiIGAEqHchtPxrRYtAr8Wl8Q==
      2016-10-13T06:37:33.474121935Z 14:37:33.473 [consensus/pbft] execDoneSync -> INFO 0d2 Replica 0 finished execution 9, trying next
      2016-10-13T06:37:33.595336893Z 14:37:33.594 [rest] processChaincodeInvokeOrQuery -> INFO 0d3 Successfully submitted invoke transaction with txid (4f010a3f-c78d-4e5c-b590-c60b601615a3)
      2016-10-13T06:37:33.596581346Z 14:37:33.595 [rest] ProcessChaincode -> INFO 0d4 REST successfully submitted invoke transaction: {"jsonrpc":"2.0","result":

      {"status":"OK","message":"4f010a3f-c78d-4e5c-b590-c60b601615a3"}

      ,"id":1}
      2016-10-13T06:37:33.842084449Z 14:37:33.841 [peer] ensureConnected -> WARN 0d5 Touch service indicates dropped connections, attempting to reconnect...
      2016-10-13T06:37:34.124749386Z 14:37:34.121 [rest] ProcessChaincode -> INFO 0d6 REST processing chaincode request...
      2016-10-13T06:37:34.124834070Z 14:37:34.122 [rest] processChaincodeInvokeOrQuery -> INFO 0d7 REST invoke chaincode...
      2016-10-13T06:37:34.124851790Z 14:37:34.123 [rest] processChaincodeInvokeOrQuery -> INFO 0d8 Local user 'lukas' is already logged in. Retrieving login token.
      2016-10-13T06:37:34.124863960Z 14:37:34.123 [devops] invokeOrQuery -> INFO 0d9 Transaction ID: 3aec3171-1458-4c49-bec4-74ee66a83c0b
      2016-10-13T06:37:34.124874346Z 14:37:34.123 [crypto] InitClient -> INFO 0da Initializing client [lukas]...
      2016-10-13T06:37:34.531384433Z 14:37:34.530 [crypto] InitClient -> INFO 0db Initializing client [lukas]...done!
      2016-10-13T06:37:34.531695119Z 14:37:34.531 [crypto] closeClientInternal -> INFO 0dc Closing client [lukas]...
      2016-10-13T06:37:34.535269117Z 14:37:34.535 [consensus/pbft] sendBatch -> INFO 0dd Creating batch with 1 requests
      2016-10-13T06:37:34.552355562Z 14:37:34.552 [consensus/pbft] executeOne -> INFO 0de Replica 0 executing/committing request batch for view=0/seqNo=10 and digest qoI9m+K4bVdcjxidzvVZYEuuXeS/m3L/c+WwiZgiWFZ2+IiUoOnVmegVJ9bRnchhvnmyCyCktRnU8ZJL0sA9zw==
      2016-10-13T06:37:34.563923547Z 14:37:34.563 [consensus/pbft] execDoneSync -> INFO 0df Replica 0 finished execution 10, trying next
      2016-10-13T06:37:34.707032954Z 14:37:34.706 [rest] processChaincodeInvokeOrQuery -> INFO 0e0 Successfully submitted invoke transaction with txid (3aec3171-1458-4c49-bec4-74ee66a83c0b)
      2016-10-13T06:37:34.707145460Z 14:37:34.706 [rest] ProcessChaincode -> INFO 0e1 REST successfully submitted invoke transaction: {"jsonrpc":"2.0","result":

      {"status":"OK","message":"3aec3171-1458-4c49-bec4-74ee66a83c0b"}

      ,"id":1}
      2016-10-13T06:37:34.844404641Z 2016/10/13 14:37:34 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:35.115076792Z 14:37:35.113 [rest] ProcessChaincode -> INFO 0e2 REST processing chaincode request...
      2016-10-13T06:37:35.115197084Z 14:37:35.114 [rest] processChaincodeInvokeOrQuery -> INFO 0e3 REST invoke chaincode...
      2016-10-13T06:37:35.116530376Z 14:37:35.116 [rest] processChaincodeInvokeOrQuery -> INFO 0e4 Local user 'lukas' is already logged in. Retrieving login token.
      2016-10-13T06:37:35.117497853Z 14:37:35.117 [devops] invokeOrQuery -> INFO 0e5 Transaction ID: bf037e08-34b4-47e9-97ad-27b33838da5a
      2016-10-13T06:37:35.117737866Z 14:37:35.117 [crypto] InitClient -> INFO 0e6 Initializing client [lukas]...
      2016-10-13T06:37:35.545628790Z 14:37:35.544 [crypto] InitClient -> INFO 0e7 Initializing client [lukas]...done!
      2016-10-13T06:37:35.546807504Z 14:37:35.545 [crypto] closeClientInternal -> INFO 0e8 Closing client [lukas]...
      2016-10-13T06:37:35.552462329Z 14:37:35.551 [consensus/pbft] sendBatch -> INFO 0e9 Creating batch with 1 requests
      2016-10-13T06:37:35.559083458Z 14:37:35.558 [consensus/pbft] executeOne -> INFO 0ea Replica 0 executing/committing request batch for view=0/seqNo=11 and digest MJKi9GhsEZR8vntS2XiRWojo8J8du48anJFphvLOE93g6/Zy4S8+xpU+54yi6zVUlkZ0g4axV5rvu9Ql5mf2nQ==
      2016-10-13T06:37:35.573009069Z 14:37:35.572 [consensus/pbft] execDoneSync -> INFO 0eb Replica 0 finished execution 11, trying next
      2016-10-13T06:37:35.707578598Z 14:37:35.706 [rest] processChaincodeInvokeOrQuery -> INFO 0ec Successfully submitted invoke transaction with txid (bf037e08-34b4-47e9-97ad-27b33838da5a)
      2016-10-13T06:37:35.707669568Z 14:37:35.706 [rest] ProcessChaincode -> INFO 0ed REST successfully submitted invoke transaction: {"jsonrpc":"2.0","result":

      {"status":"OK","message":"bf037e08-34b4-47e9-97ad-27b33838da5a"}

      ,"id":1}
      2016-10-13T06:37:36.206986228Z 14:37:36.206 [rest] ProcessChaincode -> INFO 0ee REST processing chaincode request...
      2016-10-13T06:37:36.208553268Z 14:37:36.207 [rest] processChaincodeInvokeOrQuery -> INFO 0ef REST invoke chaincode...
      2016-10-13T06:37:36.211221851Z 14:37:36.210 [rest] processChaincodeInvokeOrQuery -> INFO 0f0 Local user 'lukas' is already logged in. Retrieving login token.
      2016-10-13T06:37:36.212795599Z 14:37:36.212 [devops] invokeOrQuery -> INFO 0f1 Transaction ID: 21784685-cd46-476c-bbf7-bcb4224958b0
      2016-10-13T06:37:36.212958669Z 14:37:36.212 [crypto] InitClient -> INFO 0f2 Initializing client [lukas]...
      2016-10-13T06:37:36.610699950Z 14:37:36.609 [crypto] InitClient -> INFO 0f3 Initializing client [lukas]...done!
      2016-10-13T06:37:36.610798016Z 14:37:36.610 [crypto] closeClientInternal -> INFO 0f4 Closing client [lukas]...
      2016-10-13T06:37:36.615280778Z 14:37:36.614 [consensus/pbft] sendBatch -> INFO 0f5 Creating batch with 1 requests
      2016-10-13T06:37:36.622347777Z 14:37:36.621 [consensus/pbft] executeOne -> INFO 0f6 Replica 0 executing/committing request batch for view=0/seqNo=12 and digest 3grqqX046YtftLzvL+yGWW8raoZPY/T4WPOyqgBw4QfJdTPsL6YJ/XyGEtYAroGwBlMKTcmVbyOaWsLusHx/2Q==
      2016-10-13T06:37:36.640666038Z 14:37:36.640 [consensus/pbft] execDoneSync -> INFO 0f7 Replica 0 finished execution 12, trying next
      2016-10-13T06:37:36.749368157Z 2016/10/13 14:37:36 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:36.797182869Z 14:37:36.796 [rest] processChaincodeInvokeOrQuery -> INFO 0f8 Successfully submitted invoke transaction with txid (21784685-cd46-476c-bbf7-bcb4224958b0)
      2016-10-13T06:37:36.798528795Z 14:37:36.797 [rest] ProcessChaincode -> INFO 0f9 REST successfully submitted invoke transaction: {"jsonrpc":"2.0","result":

      {"status":"OK","message":"21784685-cd46-476c-bbf7-bcb4224958b0"}

      ,"id":1}
      2016-10-13T06:37:36.844327759Z 14:37:36.843 [peer] chatWithPeer -> ERRO 0fa Error creating connection to peer address 10.20.26.81:7051: grpc: timed out when dialing
      2016-10-13T06:37:36.845258673Z 2016/10/13 14:37:36 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:39.843999003Z 14:37:39.841 [peer] ensureConnected -> WARN 0fb Touch service indicates dropped connections, attempting to reconnect...
      2016-10-13T06:37:40.844343667Z 2016/10/13 14:37:40 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:42.507726779Z 2016/10/13 14:37:42 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:42.843955917Z 2016/10/13 14:37:42 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:42.844102530Z 14:37:42.843 [peer] chatWithPeer -> ERRO 0fc Error creating connection to peer address 10.20.26.81:7051: grpc: timed out when dialing
      2016-10-13T06:37:45.842708885Z 14:37:45.841 [peer] ensureConnected -> WARN 0fd Touch service indicates dropped connections, attempting to reconnect...
      2016-10-13T06:37:46.843545932Z 2016/10/13 14:37:46 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:48.611421816Z 2016/10/13 14:37:48 grpc: addrConn.resetTransport failed to create client transport: connection error: desc = "transport: dial tcp 10.20.26.81:7051: getsockopt: connection refused"; Reconnecting to

      {"10.20.26.81:7051" <nil>}

      2016-10-13T06:37:49.058964378Z 14:37:49.058 [peer] chatWithPeer -> ERRO 0fe Error creating connection to peer address 10.20.26.81:7051: grpc: timed out when dialing
      2016-10-13T06:37:51.818871357Z 14:37:51.818 [consensus/util] RegisterChannel -> WARN 0ff Received duplicate connection from <nil>, switching to new connection
      2016-10-13T06:37:51.828713114Z 14:37:51.828 [consensus/util] RegisterChannel -> WARN 100 Received duplicate connection from <nil>, switching to new connection
      2016-10-13T06:37:51.842903489Z 14:37:51.842 [peer] ensureConnected -> WARN 101 Touch service indicates dropped connections, attempting to reconnect...
      2016-10-13T06:37:51.850482549Z 14:37:51.850 [consensus/util] RegisterChannel -> WARN 102 Received duplicate connection from <nil>, switching to new connection
      2016-10-13T06:37:52.022731602Z 14:37:52.020 [peer] handleChat -> ERRO 103 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:

      {nam4锟?锟斤拷?锟?@锟?锟斤拷锟?$xB4I}锟
      2016-10-13T06:37:52.048799374Z 14:37:52.048 [peer] handleChat -> ERRO 104 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: {nam4锟?锟斤拷?锟?@锟?锟斤拷锟?$xB4I}


      2016-10-13T06:39:18.962489454Z 14:39:18.949 [rest] ProcessChaincode -> INFO 105 REST processing chaincode request...
      2016-10-13T06:39:18.962552617Z 14:39:18.949 [rest] processChaincodeInvokeOrQuery -> INFO 106 REST query chaincode...
      2016-10-13T06:39:18.962563091Z 14:39:18.950 [rest] processChaincodeInvokeOrQuery -> INFO 107 Local user 'lukas' is already logged in. Retrieving login token.
      2016-10-13T06:39:18.962570168Z 14:39:18.950 [devops] invokeOrQuery -> INFO 108 Transaction ID: c55b0c8d-e50c-4027-b35a-e9d919bb30ff
      2016-10-13T06:39:18.962575451Z 14:39:18.950 [crypto] InitClient -> INFO 109 Initializing client [lukas]...
      2016-10-13T06:39:19.148554725Z 14:39:19.148 [crypto] InitClient -> INFO 10a Initializing client [lukas]...done!
      2016-10-13T06:39:19.152000888Z 14:39:19.151 [crypto] closeClientInternal -> INFO 10b Closing client [lukas]...
      2016-10-13T06:39:19.240486787Z 14:39:19.240 [rest] processChaincodeInvokeOrQuery -> INFO 10c Successfully queried chaincode: 9999989
      2016-10-13T06:39:19.240573389Z 14:39:19.240 [rest] ProcessChaincode -> INFO 10d REST successfully query chaincode: {"jsonrpc":"2.0","result":

      {"status":"OK","message":"9999989"}

      ,"id":5}
      2016-10-13T06:40:38.453276094Z 14:40:38.452 [consensus/pbft] sendBatch -> INFO 10e Creating batch with 1 requests
      2016-10-13T06:40:38.455563360Z 14:40:38.455 [consensus/pbft] executeOne -> INFO 10f Replica 0 executing/committing request batch for view=0/seqNo=13 and digest N4vgPTO505CtdDiAO3mzjn9C6jomua50FiEXGycpRyh1JUgsMgngRwPml/PLtYnO9ZI66IWcyyPPsssMJ4VLmA==
      2016-10-13T06:40:38.460485970Z 14:40:38.460 [consensus/pbft] execDoneSync -> INFO 110 Replica 0 finished execution 13, trying next
      2016-10-13T06:40:48.465499225Z 14:40:48.464 [consensus/pbft] recvViewChange -> INFO 111 Replica 0 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:50.467753022Z 14:40:50.467 [consensus/pbft] recvViewChange -> INFO 112 Replica 0 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:50.467988605Z 14:40:50.467 [consensus/pbft] recvViewChange -> WARN 113 Replica 0 already has a view change message for view 1 from replica 3
      2016-10-13T06:40:52.494670936Z 14:40:52.494 [consensus/pbft] recvViewChange -> INFO 114 Replica 0 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:52.495597126Z 14:40:52.494 [consensus/pbft] recvViewChange -> WARN 115 Replica 0 already has a view change message for view 1 from replica 3
      2016-10-13T06:40:54.478574022Z 14:40:54.477 [consensus/pbft] recvViewChange -> INFO 116 Replica 0 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:54.478752042Z 14:40:54.478 [consensus/pbft] recvViewChange -> WARN 117 Replica 0 already has a view change message for view 1 from replica 3
      2016-10-13T06:40:56.479320327Z 14:40:56.478 [consensus/pbft] recvViewChange -> INFO 118 Replica 0 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:56.479451685Z 14:40:56.479 [consensus/pbft] recvViewChange -> WARN 119 Replica 0 already has a view change message for view 1 from replica 3
      2016-10-13T06:40:58.481718209Z 14:40:58.481 [consensus/pbft] recvViewChange -> INFO 11a Replica 0 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:40:58.481788220Z 14:40:58.481 [consensus/pbft] recvViewChange -> WARN 11b Replica 0 already has a view change message for view 1 from replica 3
      2016-10-13T06:41:00.487043120Z 14:41:00.486 [consensus/pbft] recvViewChange -> INFO 11c Replica 0 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:41:00.487322230Z 14:41:00.487 [consensus/pbft] recvViewChange -> WARN 11d Replica 0 already has a view change message for view 1 from replica 3
      2016-10-13T06:41:02.489947973Z 14:41:02.489 [consensus/pbft] recvViewChange -> INFO 11e Replica 0 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:41:02.490824393Z 14:41:02.490 [consensus/pbft] recvViewChange -> WARN 11f Replica 0 already has a view change message for view 1 from replica 3
      2016-10-13T06:41:04.494719254Z 14:41:04.493 [consensus/pbft] recvViewChange -> INFO 120 Replica 0 received view-change from replica 3, v:1, h:0, |C|:1, |P|:2, |Q|:2
      2016-10-13T06:41:04.495724962Z 14:41:04.495 [consensus/pbft] recvViewChange -> WARN 121 Replica 0 already has a view change message for view 1 from replica 3

      Attachments

        Issue Links

          Activity

            People

              Unassigned Unassigned
              frankylu Frank Lu
              Votes:
              1 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: