search

hyperledger / fabric-samples

Samples for Hyperledger Fabric
https://wiki.hyperledger.org/display/fabric
Apache License 2.0
2.81k stars 3.4k forks source link

test-network-k8s: "./network chaincode deploy" crashed on installing chaincode, error on invoke #558

Closed Sullson closed 2 years ago

Sullson commented 2 years ago

Hey,

so I installed and verified everything according to "Quickstart", but it seems that deploy command did not finish:

root@vmblockchainkubernetes:/home/michal/test-network-k8s# ./network chaincode deploy
Deploying chaincode "asset-transfer-basic":
✅ - Packaging chaincode folder chaincode/asset-transfer-basic ...
✅ - Transferring chaincode archive to org1 ...
✅ - Installing chaincode for org org1 ...
☠️

When trying to invoke the chaincode I get following message:

root@vmblockchainkubernetes:/home/michal/test-network-k8s# ./network chaincode invoke '{"Args":["CreateAsset","1","blue","35","tom","1000"]}'
Error: endorsement failure during invoke. response: status:500 message:"make sure the chaincode asset-transfer-basic has been successfully defined on channel mychannel and try again: chaincode asset-transfer-basic not found"

I verified pod's logs:

2021-12-12 11:04:01.981 UTC [core.comm] ServerHandshake -> DEBU 2e9 Server TLS handshake completed in 1.104809ms server=PeerServer remoteaddress=10.244.0.22:32786
2021-12-12 11:04:01.983 UTC [core.comm] ServerHandshake -> DEBU 2ea Server TLS handshake completed in 973.808µs server=PeerServer remoteaddress=10.244.0.22:32788
2021-12-12 11:04:01.986 UTC [endorser] ProcessProposal -> DEBU 2eb request from 10.244.0.22:32786
2021-12-12 11:04:01.987 UTC [endorser] Validate -> DEBU 2ec creator is valid channel=mychannel txID=62681fff mspID=Org1MSP
2021-12-12 11:04:01.987 UTC [endorser] Validate -> DEBU 2ed signature is valid channel=mychannel txID=62681fff mspID=Org1MSP
2021-12-12 11:04:01.987 UTC [blkstorage] retrieveTransactionByID -> DEBU 2ee retrieveTransactionByID() - txId = [62681fff23b2d68bdce353e935674f3348db980ed02a2e1624df1f9a22a11784]
2021-12-12 11:04:01.987 UTC [aclmgmt] CheckACL -> DEBU 2ef acl policy not found in config for resource peer/Propose
2021-12-12 11:04:01.987 UTC [lockbasedtxmgr] NewTxSimulator -> DEBU 2f0 constructing new tx simulator
2021-12-12 11:04:01.987 UTC [lockbasedtxmgr] newQueryExecutor -> DEBU 2f1 constructing new query executor txid = [62681fff23b2d68bdce353e935674f3348db980ed02a2e1624df1f9a22a11784]
2021-12-12 11:04:01.988 UTC [lockbasedtxmgr] newTxSimulator -> DEBU 2f2 constructing new tx simulator txid = [62681fff23b2d68bdce353e935674f3348db980ed02a2e1624df1f9a22a11784]
2021-12-12 11:04:01.988 UTC [stateleveldb] GetState -> DEBU 2f3 GetState(). ns=_lifecycle, key=namespaces/fields/asset-transfer-basic/Sequence
2021-12-12 11:04:01.988 UTC [stateleveldb] GetState -> DEBU 2f4 GetState(). ns=lscc, key=asset-transfer-basic
2021-12-12 11:04:01.988 UTC [lockbasedtxmgr] Done -> DEBU 2f5 Done with transaction simulation / query execution [62681fff23b2d68bdce353e935674f3348db980ed02a2e1624df1f9a22a11784]
2021-12-12 11:04:01.988 UTC [endorser] ProcessProposal -> WARN 2f6 Failed to invoke chaincode channel=mychannel chaincode=asset-transfer-basic error="make sure the chaincode asset-transfer-basic has been successfully defined on channel mychannel and try again: chaincode asset-transfer-basic not found"
2021-12-12 11:04:01.988 UTC [comm.grpc.server] 1 -> INFO 2f7 unary call completed grpc.service=protos.Endorser grpc.method=ProcessProposal grpc.peer_address=10.244.0.22:32786 grpc.code=OK grpc.call_duration=1.711115ms

ok, seems its not installed, but when I checked for logs after the deployment, it seems like chaincode was installed properly:

2021-12-12 11:01:52.909 UTC [core.comm] ServerHandshake -> DEBU 2ca Server TLS handshake completed in 1.343111ms server=PeerServer remoteaddress=10.244.0.22:59428
2021-12-12 11:01:52.912 UTC [core.comm] ServerHandshake -> DEBU 2cb Server TLS handshake completed in 1.101309ms server=PeerServer remoteaddress=10.244.0.22:59430
2021-12-12 11:01:52.913 UTC [endorser] ProcessProposal -> DEBU 2cc request from 10.244.0.22:59428
2021-12-12 11:01:52.913 UTC [endorser] Validate -> DEBU 2cd creator is valid channel= txID=7d94c182 mspID=Org1MSP
2021-12-12 11:01:52.913 UTC [endorser] Validate -> DEBU 2ce signature is valid channel= txID=7d94c182 mspID=Org1MSP
2021-12-12 11:01:52.913 UTC [chaincode] CheckInvocation -> DEBU 2cf [7d94c182] getting chaincode data for _lifecycle on channel
2021-12-12 11:01:52.913 UTC [chaincode] Execute -> DEBU 2d0 Entry
2021-12-12 11:01:52.914 UTC [lifecycle] InstallChaincode -> DEBU 2d1 received invocation of InstallChaincode for install package 1f8b0800a0d6b56100034bce4f49d52b492cd24baf62a015300002331313300d04e8b4...
2021-12-12 11:01:52.914 UTC [ccprovider] MetadataAsTarEntries -> DEBU 2d2 Created metadata tar
2021-12-12 11:01:52.919 UTC [chaincode.externalbuilder.ccs-builder] waitForExit -> INFO 2d3 ::Detect 002 command=detect
2021-12-12 11:01:52.919 UTC [chaincode.externalbuilder.ccs-builder] waitForExit -> INFO 2d4 ::Type detected as external command=detect
2021-12-12 11:01:52.922 UTC [chaincode.externalbuilder.ccs-builder] waitForExit -> INFO 2d5 ::Build command=build
2021-12-12 11:01:52.922 UTC [chaincode.externalbuilder.ccs-builder] waitForExit -> INFO 2d6 ::Type detected as external command=build
2021-12-12 11:01:52.925 UTC [chaincode.externalbuilder.ccs-builder] waitForExit -> INFO 2d7 ::Build command=release
2021-12-12 11:01:52.925 UTC [chaincode.externalbuilder.ccs-builder] waitForExit -> INFO 2d8 ::Type detected as external command=release
2021-12-12 11:01:52.926 UTC [lifecycle] ProcessInstallEvent -> DEBU 2d9 ProcessInstallEvent() - localChaincode = &{basic_1.0:43298a391987f3a5af7609957d1306343b9999dc32e799f95eca1525b6ef95fb external  basic_1.0}
2021-12-12 11:01:52.926 UTC [chaincode.externalbuilder] PackageMetadata -> DEBU 2da Walking package release dir '/var/hyperledger/fabric/data/org1-peer1.org1.example.com/externalbuilder/builds/basic_1.0-43298a391987f3a5af7609957d1306343b9999dc32e799f95eca1525b6ef95fb/release'
2021-12-12 11:01:52.926 UTC [chaincode.externalbuilder] func1 -> DEBU 2db Adding file '/var/hyperledger/fabric/data/org1-peer1.org1.example.com/externalbuilder/builds/basic_1.0-43298a391987f3a5af7609957d1306343b9999dc32e799f95eca1525b6ef95fb/release' to tar with header name 'META-INF/'
2021-12-12 11:01:52.926 UTC [chaincode.externalbuilder] func1 -> DEBU 2dc Adding file '/var/hyperledger/fabric/data/org1-peer1.org1.example.com/externalbuilder/builds/basic_1.0-43298a391987f3a5af7609957d1306343b9999dc32e799f95eca1525b6ef95fb/release/chaincode' to tar with header name 'META-INF/chaincode/'
2021-12-12 11:01:52.927 UTC [chaincode.externalbuilder] func1 -> DEBU 2de Adding file '/var/hyperledger/fabric/data/org1-peer1.org1.example.com/externalbuilder/builds/basic_1.0-43298a391987f3a5af7609957d1306343b9999dc32e799f95eca1525b6ef95fb/release/chaincode/server' to tar with header name 'META-INF/chaincode/server/'
2021-12-12 11:01:52.927 UTC [chaincode.externalbuilder] func1 -> DEBU 2df Adding file '/var/hyperledger/fabric/data/org1-peer1.org1.example.com/externalbuilder/builds/basic_1.0-43298a391987f3a5af7609957d1306343b9999dc32e799f95eca1525b6ef95fb/release/chaincode/server/connection.json' to tar with header name 'META-INF/chaincode/server/connection.json'
2021-12-12 11:01:52.926 UTC [lifecycle] Work -> DEBU 2dd skipping build of chaincode 'basic_1.0:43298a391987f3a5af7609957d1306343b9999dc32e799f95eca1525b6ef95fb' as it is already in progress
2021-12-12 11:01:52.927 UTC [lifecycle] InstallChaincode -> INFO 2e0 Successfully installed chaincode with package ID 'basic_1.0:43298a391987f3a5af7609957d1306343b9999dc32e799f95eca1525b6ef95fb'
2021-12-12 11:01:52.927 UTC [chaincode] handleMessage -> DEBU 2e1 [7d94c182] Fabric side handling ChaincodeMessage of type: COMPLETED in state ready
2021-12-12 11:01:52.927 UTC [chaincode] Notify -> DEBU 2e2 [7d94c182] notifying Txid:7d94c182fe8037a629a96e0aa5468b78d45446f40726d778496f890b9d29d39a, channelID:
2021-12-12 11:01:52.927 UTC [chaincode] Execute -> DEBU 2e3 Exit
2021-12-12 11:01:52.927 UTC [endorser] callChaincode -> INFO 2e4 finished chaincode: _lifecycle duration: 13ms channel= txID=7d94c182
2021-12-12 11:01:52.927 UTC [comm.grpc.server] 1 -> INFO 2e5 unary call completed grpc.service=protos.Endorser grpc.method=ProcessProposal grpc.peer_address=10.244.0.22:59428 grpc.code=OK grpc.call_duration=14.416925ms

so I checked with "peer" command if chaincode was installed and here is the result:

root@vmblockchainkubernetes:/home/michal/test-network-k8s# kubectl exec -n test-network deploy/org1-peer1 -- peer chaincode list --installed
Defaulted container "main" out of: main, fabric-ccs-builder (init)
2021-12-12 11:08:59.469 UTC [bccsp] GetDefault -> DEBU 001 Before using BCCSP, please call InitFactories(). Falling back to bootBCCSP.
2021-12-12 11:08:59.471 UTC [bccsp] GetDefault -> DEBU 002 Before using BCCSP, please call InitFactories(). Falling back to bootBCCSP.
2021-12-12 11:08:59.483 UTC [bccsp] GetDefault -> DEBU 003 Before using BCCSP, please call InitFactories(). Falling back to bootBCCSP.
2021-12-12 11:08:59.485 UTC [bccsp_sw] openKeyStore -> DEBU 004 KeyStore opened at [/var/hyperledger/fabric/organizations/peerOrganizations/org1.example.com/peers/org1-peer1.org1.example.com/msp/keystore]...done
2021-12-12 11:08:59.486 UTC [bccsp_sw] loadPrivateKey -> DEBU 005 Loading private key [ce2898fb23e9a5ef541fc1f6189f7ef506a4ed0d57d2b1675ef474c3cbd304ae] at [/var/hyperledger/fabric/organizations/peerOrganizations/org1.example.com/peers/org1-peer1.org1.example.com/msp/keystore/ce2898fb23e9a5ef541fc1f6189f7ef506a4ed0d57d2b1675ef474c3cbd304ae_sk]...
2021-12-12 11:08:59.497 UTC [comm.tls] ClientHandshake -> DEBU 006 Client TLS handshake completed in 1.818416ms remoteaddress=10.96.42.195:7051
2021-12-12 11:08:59.500 UTC [comm.tls] ClientHandshake -> DEBU 007 Client TLS handshake completed in 1.397112ms remoteaddress=10.96.42.195:7051
Error: bad response: 500 - access denied for [getinstalledchaincodes]: Failed verifying that proposal's creator satisfies local MSP principal during channelless check policy with policy [Admins]: [The identity is not an admin under this MSP [Org1MSP]: The identity does not contain OU [ADMIN], MSP: [Org1MSP]]
command terminated with exit code 1

Seems that maybe something is not ok with certificates, I had no error though and it seems all pods are deployed:

NAME                                  READY   STATUS    RESTARTS   AGE
pod/org0-admin-cli-54f58b4854-vrt5q   1/1     Running   0          51m
pod/org0-ecert-ca-794c88b566-ltxvf    1/1     Running   0          53m
pod/org0-orderer1-7c5b8ffd8-8d2hp     1/1     Running   0          53m
pod/org0-orderer2-66fbccf96-2tj8r     1/1     Running   0          53m
pod/org0-orderer3-5d66b57d64-phnsq    1/1     Running   0          53m
pod/org0-tls-ca-7b57d675f8-5nftm      1/1     Running   0          54m
pod/org1-admin-cli-78945bf58-nvb87    1/1     Running   0          51m
pod/org1-ecert-ca-566f79bc4d-4z5l9    1/1     Running   0          53m
pod/org1-peer1-54f767569c-chcsp       1/1     Running   0          53m
pod/org1-peer2-b5659c784-glx5t        1/1     Running   0          53m
pod/org1-tls-ca-c6685b4cb-k8smd       1/1     Running   0          54m
pod/org2-admin-cli-76d6784799-mdc4q   1/1     Running   0          51m
pod/org2-ecert-ca-5d55c7f974-b8gsm    1/1     Running   0          53m
pod/org2-peer1-6f97b8df86-zl9hl       1/1     Running   0          53m
pod/org2-peer2-585cc87cb5-jf64t       1/1     Running   0          53m
pod/org2-tls-ca-85959dcf9d-2hqmj      1/1     Running   0          54m

NAME                            TYPE        CLUSTER-IP      EXTERNAL-IP   PORT(S)                      AGE
service/org0-ecert-ca           ClusterIP   10.96.69.255    <none>        443/TCP                      53m
service/org0-orderer1           ClusterIP   10.96.113.30    <none>        6050/TCP,8443/TCP,9443/TCP   53m
service/org0-orderer2           ClusterIP   10.96.124.49    <none>        6050/TCP,8443/TCP,9443/TCP   53m
service/org0-orderer3           ClusterIP   10.96.145.227   <none>        6050/TCP,8443/TCP,9443/TCP   53m
service/org0-tls-ca             ClusterIP   10.96.219.138   <none>        443/TCP                      54m
service/org1-ecert-ca           ClusterIP   10.96.185.225   <none>        443/TCP                      53m
service/org1-peer-gateway-svc   ClusterIP   10.96.209.244   <none>        7051/TCP                     53m
service/org1-peer1              ClusterIP   10.96.42.195    <none>        7051/TCP,7052/TCP,9443/TCP   53m
service/org1-peer2              ClusterIP   10.96.183.96    <none>        7051/TCP,7052/TCP,9443/TCP   53m
service/org1-tls-ca             ClusterIP   10.96.111.103   <none>        443/TCP                      54m
service/org2-ecert-ca           ClusterIP   10.96.14.117    <none>        443/TCP                      53m
service/org2-peer-gateway-svc   ClusterIP   10.96.157.9     <none>        7051/TCP                     53m
service/org2-peer1              ClusterIP   10.96.232.145   <none>        7051/TCP,7052/TCP,9443/TCP   53m
service/org2-peer2              ClusterIP   10.96.197.98    <none>        7051/TCP,7052/TCP,9443/TCP   53m
service/org2-tls-ca             ClusterIP   10.96.61.214    <none>        443/TCP                      54m

To be honest I have no idea how to continue from that, would be awesome if someone could give me a hand. I am performing this install on Ubuntu 18 on Azure VM B2ms - 2vcpu, 8RAM (planning to go for AKS but for now I use local "kind" k8s).

Cheers, Sullson

Sullson commented 2 years ago

Tried again after last update and clean installation - still the same error but this time it seems that install process did not stop on first peer but the second one:

Deploying chaincode "asset-transfer-basic":
✅ - Packaging chaincode folder chaincode/asset-transfer-basic ...
✅ - Transferring chaincode archive to org1 ...
✅ - Installing chaincode for org org1  peer peer1 ...
✅ - Installing chaincode for org org1  peer peer2 ...
☠️

what is interesting, both peers have exactly the same logs around the installation, but still the process of "./network chaincode deploy" stopped after second one this time:

Peer1:

2021-12-23 13:39:47.757 UTC 0178 DEBU [core.comm] ServerHandshake -> Server TLS handshake completed in 1.349586ms server=PeerServer remoteaddress=10.244.0.22:58540
2021-12-23 13:39:47.760 UTC 0179 DEBU [core.comm] ServerHandshake -> Server TLS handshake completed in 1.082969ms server=PeerServer remoteaddress=10.244.0.22:58542
2021-12-23 13:39:47.761 UTC 017a DEBU [endorser] ProcessProposal -> request from 10.244.0.22:58540
2021-12-23 13:39:47.761 UTC 017b DEBU [endorser] Validate -> creator is valid channel= txID=b152be6f mspID=Org1MSP
2021-12-23 13:39:47.761 UTC 017c DEBU [endorser] Validate -> signature is valid channel= txID=b152be6f mspID=Org1MSP
2021-12-23 13:39:47.761 UTC 017d DEBU [chaincode] CheckInvocation -> [b152be6f] getting chaincode data for _lifecycle on channel
2021-12-23 13:39:47.761 UTC 017e DEBU [chaincode] Execute -> Entry
2021-12-23 13:39:47.761 UTC 017f DEBU [aclmgmt] CheckACL -> Applying default access policy for resource channel= policy=Admins resource=_lifecycle/InstallChaincode
2021-12-23 13:39:47.762 UTC 0180 DEBU [lifecycle] InstallChaincode -> received invocation of InstallChaincode for install package 1f8b0800237cc46100034bce4f49d52b492cd24baf62a015300002331313300d04e8b4...
2021-12-23 13:39:47.762 UTC 0181 DEBU [ccprovider] MetadataAsTarEntries -> Created metadata tar
2021-12-23 13:39:47.767 UTC 0182 INFO [chaincode.externalbuilder.ccaas_builder] waitForExit -> ::Detect command=detect
2021-12-23 13:39:47.767 UTC 0183 INFO [chaincode.externalbuilder.ccaas_builder] waitForExit -> ::Type detected as ccaas command=detect
2021-12-23 13:39:47.771 UTC 0184 INFO [chaincode.externalbuilder.ccaas_builder] waitForExit -> ::Build command=build
2021-12-23 13:39:47.771 UTC 0185 INFO [chaincode.externalbuilder.ccaas_builder] waitForExit -> ::Build phase completed command=build
2021-12-23 13:39:47.773 UTC 0186 INFO [chaincode.externalbuilder.ccaas_builder] waitForExit -> ::Release command=release
2021-12-23 13:39:47.773 UTC 0187 INFO [chaincode.externalbuilder.ccaas_builder] waitForExit -> ::Release phase completed command=release
2021-12-23 13:39:47.774 UTC 0188 DEBU [lifecycle] ProcessInstallEvent -> ProcessInstallEvent() - localChaincode = &{basic_1.0:a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f ccaas  basic_1.0}
2021-12-23 13:39:47.774 UTC 0189 DEBU [chaincode.externalbuilder] PackageMetadata -> Walking package release dir '/var/hyperledger/fabric/data/org1-peer1.org1.example.com/externalbuilder/builds/basic_1.0-a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f/release'
2021-12-23 13:39:47.775 UTC 018a DEBU [lifecycle] Work -> skipping build of chaincode 'basic_1.0:a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f' as it is already in progress
2021-12-23 13:39:47.775 UTC 018b DEBU [chaincode.externalbuilder] func1 -> Adding file '/var/hyperledger/fabric/data/org1-peer1.org1.example.com/externalbuilder/builds/basic_1.0-a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f/release' to tar with header name 'META-INF/'
2021-12-23 13:39:47.775 UTC 018c DEBU [chaincode.externalbuilder] func1 -> Adding file '/var/hyperledger/fabric/data/org1-peer1.org1.example.com/externalbuilder/builds/basic_1.0-a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f/release/chaincode' to tar with header name 'META-INF/chaincode/'
2021-12-23 13:39:47.775 UTC 018d DEBU [chaincode.externalbuilder] func1 -> Adding file '/var/hyperledger/fabric/data/org1-peer1.org1.example.com/externalbuilder/builds/basic_1.0-a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f/release/chaincode/server' to tar with header name 'META-INF/chaincode/server/'
2021-12-23 13:39:47.775 UTC 018e DEBU [chaincode.externalbuilder] func1 -> Adding file '/var/hyperledger/fabric/data/org1-peer1.org1.example.com/externalbuilder/builds/basic_1.0-a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f/release/chaincode/server/connection.json' to tar with header name 'META-INF/chaincode/server/connection.json'
2021-12-23 13:39:47.775 UTC 018f INFO [lifecycle] InstallChaincode -> Successfully installed chaincode with package ID 'basic_1.0:a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f'
2021-12-23 13:39:47.775 UTC 0190 DEBU [chaincode] handleMessage -> [b152be6f] Fabric side handling ChaincodeMessage of type: COMPLETED in state ready
2021-12-23 13:39:47.775 UTC 0191 DEBU [chaincode] Notify -> [b152be6f] notifying Txid:b152be6f83f3d366122863568831d88a9265933b548cf6667f829604d4ae18c6, channelID:
2021-12-23 13:39:47.775 UTC 0192 DEBU [chaincode] Execute -> Exit
2021-12-23 13:39:47.775 UTC 0193 INFO [endorser] callChaincode -> finished chaincode: _lifecycle duration: 14ms channel= txID=b152be6f
2021-12-23 13:39:47.775 UTC 0194 INFO [comm.grpc.server] 1 -> unary call completed grpc.service=protos.Endorser grpc.method=ProcessProposal grpc.peer_address=10.244.0.22:58540 grpc.code=OK grpc.call_duration=15.023557ms

Peer 2:

2021-12-23 13:39:47.977 UTC 016d DEBU [core.comm] ServerHandshake -> Server TLS handshake completed in 1.281482ms server=PeerServer remoteaddress=10.244.0.22:60912
2021-12-23 13:39:47.980 UTC 016e DEBU [core.comm] ServerHandshake -> Server TLS handshake completed in 2.481458ms server=PeerServer remoteaddress=10.244.0.22:60914
2021-12-23 13:39:47.982 UTC 016f DEBU [endorser] ProcessProposal -> request from 10.244.0.22:60912
2021-12-23 13:39:47.982 UTC 0170 DEBU [endorser] Validate -> creator is valid channel= txID=2f5e2833 mspID=Org1MSP
2021-12-23 13:39:47.982 UTC 0171 DEBU [endorser] Validate -> signature is valid channel= txID=2f5e2833 mspID=Org1MSP
2021-12-23 13:39:47.982 UTC 0172 DEBU [chaincode] CheckInvocation -> [2f5e2833] getting chaincode data for _lifecycle on channel
2021-12-23 13:39:47.982 UTC 0173 DEBU [chaincode] Execute -> Entry
2021-12-23 13:39:47.983 UTC 0174 DEBU [aclmgmt] CheckACL -> Applying default access policy for resource channel= policy=Admins resource=_lifecycle/InstallChaincode
2021-12-23 13:39:47.983 UTC 0175 DEBU [lifecycle] InstallChaincode -> received invocation of InstallChaincode for install package 1f8b0800237cc46100034bce4f49d52b492cd24baf62a015300002331313300d04e8b4...
2021-12-23 13:39:47.983 UTC 0176 DEBU [ccprovider] MetadataAsTarEntries -> Created metadata tar
2021-12-23 13:39:47.990 UTC 0177 INFO [chaincode.externalbuilder.ccaas_builder] waitForExit -> ::Detect command=detect
2021-12-23 13:39:47.990 UTC 0178 INFO [chaincode.externalbuilder.ccaas_builder] waitForExit -> ::Type detected as ccaas command=detect
2021-12-23 13:39:47.993 UTC 0179 INFO [chaincode.externalbuilder.ccaas_builder] waitForExit -> ::Build command=build
2021-12-23 13:39:47.993 UTC 017a INFO [chaincode.externalbuilder.ccaas_builder] waitForExit -> ::Build phase completed command=build
2021-12-23 13:39:47.996 UTC 017b INFO [chaincode.externalbuilder.ccaas_builder] waitForExit -> ::Release command=release
2021-12-23 13:39:47.996 UTC 017c INFO [chaincode.externalbuilder.ccaas_builder] waitForExit -> ::Release phase completed command=release
2021-12-23 13:39:47.997 UTC 017d DEBU [lifecycle] ProcessInstallEvent -> ProcessInstallEvent() - localChaincode = &{basic_1.0:a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f ccaas  basic_1.0}
2021-12-23 13:39:47.997 UTC 017e DEBU [lifecycle] Work -> skipping build of chaincode 'basic_1.0:a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f' as it is already in progress
2021-12-23 13:39:47.997 UTC 017f DEBU [chaincode.externalbuilder] PackageMetadata -> Walking package release dir '/var/hyperledger/fabric/data/org1-peer2.org1.example.com/externalbuilder/builds/basic_1.0-a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f/release'
2021-12-23 13:39:47.997 UTC 0180 DEBU [chaincode.externalbuilder] func1 -> Adding file '/var/hyperledger/fabric/data/org1-peer2.org1.example.com/externalbuilder/builds/basic_1.0-a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f/release' to tar with header name 'META-INF/'
2021-12-23 13:39:47.998 UTC 0181 DEBU [chaincode.externalbuilder] func1 -> Adding file '/var/hyperledger/fabric/data/org1-peer2.org1.example.com/externalbuilder/builds/basic_1.0-a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f/release/chaincode' to tar with header name 'META-INF/chaincode/'
2021-12-23 13:39:47.998 UTC 0182 DEBU [chaincode.externalbuilder] func1 -> Adding file '/var/hyperledger/fabric/data/org1-peer2.org1.example.com/externalbuilder/builds/basic_1.0-a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f/release/chaincode/server' to tar with header name 'META-INF/chaincode/server/'
2021-12-23 13:39:47.998 UTC 0183 DEBU [chaincode.externalbuilder] func1 -> Adding file '/var/hyperledger/fabric/data/org1-peer2.org1.example.com/externalbuilder/builds/basic_1.0-a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f/release/chaincode/server/connection.json' to tar with header name 'META-INF/chaincode/server/connection.json'
2021-12-23 13:39:47.998 UTC 0184 INFO [lifecycle] InstallChaincode -> Successfully installed chaincode with package ID 'basic_1.0:a52148c6e35eb24e2dd55c0bfa5f8d7cc29a12547c214424ae3298329228a42f'
2021-12-23 13:39:47.998 UTC 0185 DEBU [chaincode] handleMessage -> [2f5e2833] Fabric side handling ChaincodeMessage of type: COMPLETED in state ready
2021-12-23 13:39:47.998 UTC 0186 DEBU [chaincode] Notify -> [2f5e2833] notifying Txid:2f5e28338a0ee74dfdfd73669c0ccfba0deb28191cc5e01e20cd7e5a4508f0d5, channelID:
2021-12-23 13:39:47.998 UTC 0187 DEBU [chaincode] Execute -> Exit
2021-12-23 13:39:47.998 UTC 0188 INFO [endorser] callChaincode -> finished chaincode: _lifecycle duration: 15ms channel= txID=2f5e2833
2021-12-23 13:39:47.998 UTC 0189 INFO [comm.grpc.server] 1 -> unary call completed grpc.service=protos.Endorser grpc.method=ProcessProposal grpc.peer_address=10.244.0.22:60912 grpc.code=OK grpc.call_duration=16.597258ms
jkneubuh commented 2 years ago

Hi @Sullson

The network script still could use some work around reporting the output from a failed command - as you found it does not always report the underlying error when one of the routines or k8s invocations crashes behind the scenes. ☠️

There may have been some issues a couple of weeks ago related to the embedded / default chaincode builder, but these should have been sorted out with the 2.4.1 release. Can you post the tail end of the network-debug.log file? (This will include all of the output from the shell commands running behind the scenes. The ☠️ means that one of the sub-commands executed with a non-zero error.)

Also it looks like the chaincode installed OK on both peers... I think this may be an error up in the ./network script, NOT in the remote peer command.

Is there any chance you do NOT have jq installed on your machine? This is new utility pulled into the script and I don't believe it's being checked in the pre-requisites. I think the program is crashing on your machine here: 

which jq
which shasum
Sullson commented 2 years ago

Hey @jkneubuh

that's it, amazing catch, thanks a lot!

I installed all requirements (docker, kind, kubectl) on clean Ubuntu 18.04 and jq was the only thing missing (things like ca-certificates for example were docker requirements so they were in place).

It might be benefitial to just add theese into main README file and thanks to that spare some time on ./network logging ;)

Thanks again!

Sull