踩坑之chaincode无法实例化-"container exi
2019-08-21 本文已影响0人
一坨云隙光
背景
希望在本地以可执行文件的形式启动peer和orderer，方便修改和调试。编译完成后，以ip为127.0.0.1启动了orderer和peer，channel创建，chaincode安装都没问题，但是到实例化这一步就卡住了。peer版本：
peer:
Version: 1.4.3
Commit SHA: 05da109eb
Go version: go1.12.7
OS/Arch: darwin/amd64
Chaincode:
Base Image Version: 0.4.15
Base Docker Namespace: hyperledger
Base Docker Label: org.hyperledger.fabric
Docker Namespace: hyperledger
现象
实例化之前的步骤省略，在chaincode实例化时，命令行提示：
Error: could not assemble transaction, err proposal response was not successful, error code 500, msg chaincode registration failed: container exited with 0
实例化chaincode的CLI端
与此同时，peer端的信息如下：
实例化chaincode的peer端
使用docker ps发现没有container，但是docker images可以看见chaincode镜像已经生成了。
查看docker容器和镜像
解决
1.修改endorser日志级别为debug
观察日志发现，报错为endorser，所以首先尝试将endorser的debug打开
CORE_PEER_MSPCONFIGPATH=./crypto-config/peerOrganizations/org1.net/users/Admin@org1.net/msp CORE_PEER_LOCALMSPID="Org1MSP" ./peer1 logging setlevel endorser debug
再次尝试实例化，日志并没有显示更多有价值的信息
endorser开启debug
但是观察错误信息，其中error: container exited with 0，结合chaincode image已经生成的事实，推测其实container应该也生成了，或许是因为非正常退出被删除了。。
2.日志级别全部设为debug
修改peer启动环境变量FABRIC_LOGGING_SPEC=DEBUG或者使用如下命令：
CORE_PEER_MSPCONFIGPATH=./crypto-config/peerOrganizations/org1.net/users/Admin@org1.net/msp CORE_PEER_LOCALMSPID="Org1MSP" ./peer1 logging setlogspec debug
再次尝试实例化，这回果然发现了很多有意思的地方，我省略了日志中msp和gossip的一些无关信息。
2019-08-21 10:26:50.170 CST [protoutils] checkSignatureFromCreator -> DEBU 1f9 begin
2019-08-21 10:26:50.170 CST [msp] GetManagerForChain -> DEBU 1fa Returning existing manager for channel 'ac'
2019-08-21 10:26:50.170 CST [protoutils] checkSignatureFromCreator -> DEBU 1fb creator is &{Org1MSP caca02f0c245f1ca10575f05ce0165b470129d9aa06d11294f3cc89d2e071724}
2019-08-21 10:26:50.170 CST [protoutils] checkSignatureFromCreator -> DEBU 1fc creator is valid
2019-08-21 10:26:50.170 CST [msp.identity] Verify -> DEBU 1fd Verify: digest = 00000000 56 56 82 9b e7 4a 89 9f ff d2 94 61 b5 b2 e6 67 |VV...J.....a...g|
00000010 6a e2 e9 c3 7f 5e fa 71 3e b8 f9 5b 25 5d cb f8 |j....^.q>..[%]..|
2019-08-21 10:26:50.170 CST [msp.identity] Verify -> DEBU 1fe Verify: sig = 00000000 30 44 02 21 00 fb e6 89 b4 6f fe 46 24 32 59 4d |0D.!.....o.F$2YM|
00000010 f6 a1 1b 48 10 c5 f3 d2 04 c5 05 0b 02 b5 fd e3 |...H............|
00000020 8c 1e 25 2b 5b 02 1f 3e 33 61 18 b7 cf cc e7 8b |..%+[..>3a......|
00000030 c4 70 ca be ec f6 21 4c 55 f4 b7 1d a4 61 2d f7 |.p....!LU....a-.|
00000040 d0 85 b5 7b d6 8b |...{..|
2019-08-21 10:26:50.170 CST [protoutils] checkSignatureFromCreator -> DEBU 1ff exits successfully
2019-08-21 10:26:50.170 CST [protoutils] validateChaincodeProposalMessage -> DEBU 200 validateChaincodeProposalMessage starts for proposal 0xc0003d6ee0, header 0xc002b864b0
2019-08-21 10:26:50.170 CST [protoutils] validateChaincodeProposalMessage -> DEBU 201 validateChaincodeProposalMessage info: header extension references chaincode name:"lscc"
2019-08-21 10:26:50.170 CST [endorser] preProcess -> DEBU 202 [ac][3297cca1] processing txid: 3297cca1db3d971a8c33ec77dacfb6692e53adcbeebc3564d8b716b55452b439
2019-08-21 10:26:50.170 CST [fsblkstorage] retrieveTransactionByID -> DEBU 203 retrieveTransactionByID() - txId = [3297cca1db3d971a8c33ec77dacfb6692e53adcbeebc3564d8b716b55452b439]
2019-08-21 10:26:50.170 CST [lockbasedtxmgr] NewTxSimulator -> DEBU 204 constructing new tx simulator
2019-08-21 10:26:50.170 CST [lockbasedtxmgr] newLockBasedTxSimulator -> DEBU 205 constructing new tx simulator txid = [3297cca1db3d971a8c33ec77dacfb6692e53adcbeebc3564d8b716b55452b439]
2019-08-21 10:26:50.170 CST [endorser] SimulateProposal -> DEBU 206 [ac][3297cca1] Entry chaincode: name:"lscc"
2019-08-21 10:26:50.170 CST [endorser] callChaincode -> INFO 207 [ac][3297cca1] Entry chaincode: name:"lscc"
2019-08-21 10:26:50.170 CST [chaincode] Execute -> DEBU 208 Entry
2019-08-21 10:26:50.178 CST [chaincode] handleMessage -> DEBU 209 [3297cca1] Fabric side handling ChaincodeMessage of type: GET_STATE in state ready
2019-08-21 10:26:50.178 CST [chaincode] HandleTransaction -> DEBU 20a [3297cca1] handling GET_STATE from chaincode
2019-08-21 10:26:50.179 CST [chaincode] HandleGetState -> DEBU 20b [3297cca1] getting state for chaincode lscc, key ex02, channel ac
2019-08-21 10:26:50.179 CST [stateleveldb] GetState -> DEBU 20c GetState(). ns=lscc, key=ex02
2019-08-21 10:26:50.179 CST [chaincode] HandleGetState -> DEBU 20d [3297cca1] No state associated with key: ex02. Sending RESPONSE with an empty payload
2019-08-21 10:26:50.179 CST [chaincode] HandleTransaction -> DEBU 20e [3297cca1] Completed GET_STATE. Sending RESPONSE
2019-08-21 10:26:50.179 CST [msp] GetManagerForChain -> DEBU 20f Returning existing manager for channel 'ac'
2019-08-21 10:26:50.179 CST [cauthdsl] func1 -> DEBU 210 0xc0025ceeb0 gate 1566354410179215000 evaluation starts
2019-08-21 10:26:50.179 CST [cauthdsl] func2 -> DEBU 211 0xc0025ceeb0 signed by 0 principal evaluation starts (used [false])
2019-08-21 10:26:50.179 CST [cauthdsl] func2 -> DEBU 212 0xc0025ceeb0 processing identity 0 with bytes of 47012a0
2019-08-21 10:26:50.179 CST [cauthdsl] func2 -> DEBU 213 0xc0025ceeb0 principal matched by identity 0
2019-08-21 10:26:50.179 CST [msp.identity] Verify -> DEBU 214 Verify: digest = 00000000 56 56 82 9b e7 4a 89 9f ff d2 94 61 b5 b2 e6 67 |VV...J.....a...g|
00000010 6a e2 e9 c3 7f 5e fa 71 3e b8 f9 5b 25 5d cb f8 |j....^.q>..[%]..|
2019-08-21 10:26:50.179 CST [msp.identity] Verify -> DEBU 215 Verify: sig = 00000000 30 44 02 21 00 fb e6 89 b4 6f fe 46 24 32 59 4d |0D.!.....o.F$2YM|
00000010 f6 a1 1b 48 10 c5 f3 d2 04 c5 05 0b 02 b5 fd e3 |...H............|
00000020 8c 1e 25 2b 5b 02 1f 3e 33 61 18 b7 cf cc e7 8b |..%+[..>3a......|
00000030 c4 70 ca be ec f6 21 4c 55 f4 b7 1d a4 61 2d f7 |.p....!LU....a-.|
00000040 d0 85 b5 7b d6 8b |...{..|
2019-08-21 10:26:50.179 CST [cauthdsl] func2 -> DEBU 216 0xc0025ceeb0 principal evaluation succeeds for identity 0
2019-08-21 10:26:50.179 CST [cauthdsl] func1 -> DEBU 217 0xc0025ceeb0 gate 1566354410179215000 evaluation succeeds
2019-08-21 10:26:50.179 CST [chaincode] handleMessage -> DEBU 218 [3297cca1] Fabric side handling ChaincodeMessage of type: PUT_STATE in state ready
2019-08-21 10:26:50.179 CST [chaincode] HandleTransaction -> DEBU 219 [3297cca1] handling PUT_STATE from chaincode
2019-08-21 10:26:50.179 CST [chaincode] HandleTransaction -> DEBU 21a [3297cca1] Completed PUT_STATE. Sending RESPONSE
2019-08-21 10:26:50.179 CST [lscc] putChaincodeCollectionData -> DEBU 21b No collection configuration specified
2019-08-21 10:26:50.179 CST [chaincode] handleMessage -> DEBU 21c [3297cca1] Fabric side handling ChaincodeMessage of type: COMPLETED in state ready
2019-08-21 10:26:50.180 CST [chaincode] Notify -> DEBU 21d [3297cca1] notifying Txid:3297cca1db3d971a8c33ec77dacfb6692e53adcbeebc3564d8b716b55452b439, channelID:ac
2019-08-21 10:26:50.180 CST [chaincode] Execute -> DEBU 21e Exit
2019-08-21 10:26:50.196 CST [chaincode] LaunchConfig -> DEBU 21f launchConfig: executable:"chaincode",Args:[chaincode,-peer.address=127.0.0.1:7052],Envs:[CORE_CHAINCODE_LOGGING_LEVEL=debug,CORE_CHAINCODE_LOGGING_SHIM=warning,CORE_CHAINCODE_LOGGING_FORMAT=%{color}%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x}%{color:reset} %{message},CORE_CHAINCODE_ID_NAME=ex02:v2,CORE_PEER_TLS_ENABLED=false],Files:[]
2019-08-21 10:26:50.196 CST [chaincode] Start -> DEBU 220 start container: ex02:v2
2019-08-21 10:26:50.196 CST [chaincode] Start -> DEBU 221 start container with args: chaincode -peer.address=127.0.0.1:7052
2019-08-21 10:26:50.196 CST [chaincode] Start -> DEBU 222 start container with env:
CORE_CHAINCODE_LOGGING_LEVEL=debug
CORE_CHAINCODE_LOGGING_SHIM=warning
CORE_CHAINCODE_LOGGING_FORMAT=%{color}%{time:2006-01-02 15:04:05.000 MST} [%{module}] %{shortfunc} -> %{level:.4s} %{id:03x}%{color:reset} %{message}
CORE_CHAINCODE_ID_NAME=ex02:v2
CORE_PEER_TLS_ENABLED=false
2019-08-21 10:26:50.196 CST [container] lockContainer -> DEBU 223 waiting for container(ex02-v2) lock
2019-08-21 10:26:50.196 CST [container] lockContainer -> DEBU 224 got container (ex02-v2) lock
2019-08-21 10:26:50.196 CST [dockercontroller] stopInternal -> DEBU 225 stopping container id=dev-peer1.org1.net-ex02-v2
2019-08-21 10:26:50.200 CST [dockercontroller] stopInternal -> DEBU 226 stop container result error="No such container: dev-peer1.org1.net-ex02-v2"
2019-08-21 10:26:50.200 CST [dockercontroller] stopInternal -> DEBU 227 killing container id=dev-peer1.org1.net-ex02-v2
2019-08-21 10:26:50.202 CST [dockercontroller] stopInternal -> DEBU 228 kill container result id=dev-peer1.org1.net-ex02-v2 error="No such container: dev-peer1.org1.net-ex02-v2"
2019-08-21 10:26:50.202 CST [dockercontroller] stopInternal -> DEBU 229 removing container id=dev-peer1.org1.net-ex02-v2
2019-08-21 10:26:50.205 CST [dockercontroller] stopInternal -> DEBU 22a remove container result id=dev-peer1.org1.net-ex02-v2 error="No such container: dev-peer1.org1.net-ex02-v2"
2019-08-21 10:26:50.205 CST [dockercontroller] createContainer -> DEBU 22b create container imageID=dev-peer1.org1.net-ex02-v2-01dbdad4fb65c8ec72d110e992de5bad1590c21cdd615da3e489e140f084ad15 containerID=dev-peer1.org1.net-ex02-v2
2019-08-21 10:26:50.205 CST [dockercontroller] getDockerHostConfig -> DEBU 22c docker container hostconfig NetworkMode: host
2019-08-21 10:26:50.357 CST [dockercontroller] createContainer -> DEBU 22d created container imageID=dev-peer1.org1.net-ex02-v2-01dbdad4fb65c8ec72d110e992de5bad1590c21cdd615da3e489e140f084ad15 containerID=dev-peer1.org1.net-ex02-v2
2019-08-21 10:26:50.682 CST [dockercontroller] Start -> DEBU 22e Started container dev-peer1.org1.net-ex02-v2
2019-08-21 10:26:50.683 CST [container] unlockContainer -> DEBU 22f container lock deleted(ex02-v2)
2019-08-21 10:26:50.683 CST [container] lockContainer -> DEBU 230 waiting for container(ex02-v2) lock
2019-08-21 10:26:50.683 CST [container] lockContainer -> DEBU 231 got container (ex02-v2) lock
2019-08-21 10:26:50.683 CST [container] unlockContainer -> DEBU 232 container lock deleted(ex02-v2)
2019-08-21 10:26:53.929 CST [chaincode] Launch -> DEBU 247 stopping due to error while launching: container exited with 0
github.com/hyperledger/fabric/core/chaincode.(*RuntimeLauncher).Launch.func1
/Users/gnli/gopath/src/github.com/Hyperledger/fabric/core/chaincode/runtime_launcher.go:63
runtime.goexit
/usr/local/Cellar/go/1.12.7/libexec/src/runtime/asm_amd64.s:1337
chaincode registration failed
2019-08-21 10:26:53.929 CST [container] lockContainer -> DEBU 248 waiting for container(ex02-v2) lock
2019-08-21 10:26:53.929 CST [container] lockContainer -> DEBU 249 got container (ex02-v2) lock
2019-08-21 10:26:53.929 CST [dockercontroller] stopInternal -> DEBU 24a stopping container id=dev-peer1.org1.net-ex02-v2
2019-08-21 10:26:53.932 CST [dockercontroller] stopInternal -> DEBU 24b stop container result error="Container not running: dev-peer1.org1.net-ex02-v2"
2019-08-21 10:26:53.932 CST [dockercontroller] stopInternal -> DEBU 24c killing container id=dev-peer1.org1.net-ex02-v2
2019-08-21 10:26:53.934 CST [dockercontroller] stopInternal -> DEBU 24d kill container result id=dev-peer1.org1.net-ex02-v2 error="Container not running: dev-peer1.org1.net-ex02-v2"
2019-08-21 10:26:53.934 CST [dockercontroller] stopInternal -> DEBU 24e removing container id=dev-peer1.org1.net-ex02-v2
2019-08-21 10:26:53.941 CST [dockercontroller] stopInternal -> DEBU 24f remove container result id=dev-peer1.org1.net-ex02-v2 error=null
2019-08-21 10:26:53.941 CST [container] unlockContainer -> DEBU 250 container lock deleted(ex02-v2)
2019-08-21 10:26:53.941 CST [chaincode] Launch -> DEBU 251 launch complete
2019-08-21 10:26:53.941 CST [chaincode] Deregister -> DEBU 252 deregister handler: ex02:v2
2019-08-21 10:26:53.941 CST [endorser] callChaincode -> INFO 253 [ac][3297cca1] Exit chaincode: name:"lscc" (3771ms)
2019-08-21 10:26:53.941 CST [endorser] SimulateProposal -> ERRO 254 [ac][3297cca1] failed to invoke chaincode name:"lscc" , error: container exited with 0
github.com/hyperledger/fabric/core/chaincode.(*RuntimeLauncher).Launch.func1
/Users/gnli/gopath/src/github.com/Hyperledger/fabric/core/chaincode/runtime_launcher.go:63
runtime.goexit
/usr/local/Cellar/go/1.12.7/libexec/src/runtime/asm_amd64.s:1337
chaincode registration failed
2019-08-21 10:26:53.941 CST [endorser] SimulateProposal -> DEBU 255 [ac][3297cca1] Exit
2019-08-21 10:26:53.941 CST [lockbasedtxmgr] Done -> DEBU 256 Done with transaction simulation / query execution [3297cca1db3d971a8c33ec77dacfb6692e53adcbeebc3564d8b716b55452b439]
2019-08-21 10:26:53.941 CST [endorser] func1 -> DEBU 257 Exit: request from 127.0.0.1:62298
2019-08-21 10:26:53.941 CST [comm.grpc.server] 1 -> INFO 258 unary call completed grpc.service=protos.Endorser grpc.method=ProcessProposal grpc.peer_address=127.0.0.1:62298 grpc.code=OK grpc.call_duration=3.771761635s
日志中可以看到完整的过程：首先验证tx发起人的身份，确认这个tx是发往channel ac的，然后开始执行lscc，可以看到传给chaincode的启动参数，其中值得注意的是-peer.address=127.0.0.1:7052；lscc不管三七二十一先把已经存在的同名container删掉（如果存在的话），接下来新建image并启动container，但是container启动没有成功，就把container删掉了（见上面日志中第DEBU 24a至DEBU 24f条），果然如此！
3.验证
到这里，我突然想起docker是有自己的网络的，而传给chaincode container的启动参数中，peer的地址是127.0.0.1，肯定是连接不上的，官方和网上的资料，大多数都是使用docker容器的方式部署网络，绑定了域名，自然不会存在我遇到的问题。应该是八九不离十了，照例还是需要验证一下，怎么验证呢？想办法在peer删除container之前将其截获。
于是再次执行实例化操作，盯紧了peer日志，抓好时机kill掉peer，然后我找到了container的身体。。
截获的chaincode容器
查看chaincode容器日志，发现docker容器果然是无法连接peer
chaincode容器日志
4.修改peer启动地址
明确了原因就简单多了，通过ifconfig查看本机ip，然后指定peer address为此ip即可。
chaincode实例化成功
当然在
/etc/hosts中绑定一个域名也可以，如添加10.100.110.54 peer1.org1.net
注意更改背书策略，否则CLI发送写tx会失败
修改背书策略
最终结果
最终结果
