CLI wallet does not unlock after bid expiration

[Rigorously]

Example with bid of 2 and locktime of 100 blocks.

> loadwallet [password]
Wallet loaded sucessfully!
> sync
Syncing wallet.. (138088/13808)
> bid 2 100 [password]
hash: [txid]
>startblockgenerator [txid]

Immediately after the last command, the CLI does not respond to input.

After the locktime of 100 blocks has passed, the CLI is expected to return control, but remains non-interactive.

[jules]

Hmm, the console should return control right after running startblockgenerator. Could I ask you to do two things?

• Tell me what platform you're running this on
• If you haven't started the node up after closing it, sending the debug7000.log file in your node directory

In the meantime, I will try it on my end and see if it is reproducible.

[jules]

@Rigorously Additionally, were you running the blindbid process? If not, that could be a possible explanation for why it got stuck.

[Rigorously]

Ubuntu 19.04 Disco Dingo

Concerning blindbid: I did not run blindbid. In issue #3 you can see my shell history.

I am afraid debug7000.log has been overwritten and I forgot to make a backup. For what it is worth, here is an excerpt.

time="2019-07-28T05:37:41-04:00" level=info msg="Selected network  testnet"
time="2019-07-28T05:37:41-04:00" level=info msg="create new instance" prefix=mempool
time="2019-07-28T05:37:41-04:00" level=info msg="running with pool type hashmap" prefix=mempool
time="2019-07-28T05:37:41-04:00" level=debug msg="Accepting messages" id=770682363 topic=tx
time="2019-07-28T05:37:41-04:00" level=debug msg="Accepting messages" id=308979280 topic=acceptedblock
time="2019-07-28T05:37:41-04:00" level=debug msg="Accepting messages" id=3850181545 topic=candidate
time="2019-07-28T05:37:41-04:00" level=debug msg="Accepting messages" id=620705887 topic=certificate
time="2019-07-28T05:37:41-04:00" level=debug msg="Accepting messages" id=1735085716 topic=acceptedblock
time="2019-07-28T05:37:41-04:00" level=info msg="RPC server listening on port 9000" process=rpc
time="2019-07-28T05:37:46-04:00" level=debug msg="connected to voucher seeder" prefix=main
time="2019-07-28T05:37:46-04:00" level=debug msg="voucher seeder challenge completed" prefix=main
time="2019-07-28T05:37:46-04:00" level=debug msg="connection established" address="46.101.79.101:7000" process=server
time="2019-07-28T05:37:46-04:00" level=debug msg="connection established" address="142.93.142.38:7000" process=server
time="2019-07-28T05:37:46-04:00" level=debug msg="connection established" address="134.209.146.102:7000" process=server
time="2019-07-28T05:37:47-04:00" level=debug msg="connection established" address="138.197.149.205:7000" process=server
time="2019-07-28T05:37:47-04:00" level=debug msg="connection established" address="142.93.156.11:7000" process=server
time="2019-07-28T05:37:47-04:00" level=debug msg="connection established" address="178.128.238.142:7000" process=server
time="2019-07-28T05:37:47-04:00" level=debug msg="connection established" address="138.68.139.222:7000" process=server
time="2019-07-28T05:37:47-04:00" level=debug msg="connection established" address="157.230.29.23:7000" process=server
time="2019-07-28T05:37:47-04:00" level=debug msg="connection established" address="142.93.130.51:7000" process=server
time="2019-07-28T05:37:47-04:00" level=debug msg="connection established" address="68.183.77.70:7000" process=server
time="2019-07-28T05:37:47-04:00" level=debug msg="connection established" address="159.203.6.189:7000" process=server
time="2019-07-28T05:37:49-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=16937
time="2019-07-28T05:37:49-04:00" level=debug msg="Start syncing from 142.93.142.38:7000" process=synchronizer
time="2019-07-28T05:37:49-04:00" level=debug msg="Local tip: height 13903 [F0f4saW1zbstTSAez3fkW5HZ7Vx3kxmhvP7uRC3n+Tk=]" process=synchronizer
time="2019-07-28T05:37:49-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=13904
time="2019-07-28T05:37:49-04:00" level=trace msg="procedure started" process="accept block"
time="2019-07-28T05:37:49-04:00" level=error msg="verifying the certificate failed: bls apk: Invalid Signature.\nG1Sig pair (length 384): 482390c44d8bbb78b8d9...\nApk H0(m) pair (length 384): 103e9287520287c70fc0..." process="accept block"
time="2019-07-28T05:37:49-04:00" level=warning msg="error when triggering callback" error="bls apk: Invalid Signature.\nG1Sig pair (length 384): 482390c44d8bbb78b8d9...\nApk H0(m) pair (length 384): 103e9287520287c70fc0..." process="event bus" topic=block
time="2019-07-28T05:37:49-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=13905
time="2019-07-28T05:37:49-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=13906

[snip]

time="2019-07-28T05:37:50-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=14402
time="2019-07-28T05:37:50-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=14403
time="2019-07-28T05:37:56-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=16938
time="2019-07-28T05:38:02-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=16939
time="2019-07-28T05:38:07-04:00" level=info msg="verified 0 transactions, overall size 0.00000 MB" prefix=mempool
time="2019-07-28T05:38:07-04:00" level=trace msg="list of the verified txs" prefix=mempool
time="2019-07-28T05:38:09-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=16940
time="2019-07-28T05:38:15-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=16941
time="2019-07-28T05:38:21-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=16942
time="2019-07-28T05:38:21-04:00" level=debug msg="Start syncing from 68.183.77.70:7000" process=synchronizer
time="2019-07-28T05:38:21-04:00" level=debug msg="Local tip: height 13903 [F0f4saW1zbstTSAez3fkW5HZ7Vx3kxmhvP7uRC3n+Tk=]" process=synchronizer
time="2019-07-28T05:38:27-04:00" level=info msg="verified 0 transactions, overall size 0.00000 MB" prefix=mempool
time="2019-07-28T05:38:27-04:00" level=trace msg="list of the verified txs" prefix=mempool
time="2019-07-28T05:38:28-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=16943
time="2019-07-28T05:38:34-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=16944
time="2019-07-28T05:38:40-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=16945
time="2019-07-28T05:38:47-04:00" level=info msg="verified 0 transactions, overall size 0.00000 MB" prefix=mempool
time="2019-07-28T05:38:47-04:00" level=trace msg="list of the verified txs" prefix=mempool
time="2019-07-28T05:39:02-04:00" level=debug msg="block received" our height=13903 process=synchronizer received block height=16946
time="2019-07-28T05:39:02-04:00" level=debug msg="Start syncing from 142.93.142.38:7000" process=synchronizer
time="2019-07-28T05:39:02-04:00" level=debug msg="Local tip: height 13903 [F0f4saW1zbstTSAez3fkW5HZ7Vx3kxmhvP7uRC3n+Tk=]" process=synchronizer
time="2019-07-28T05:39:07-04:00" level=info msg="verified 0 transactions, overall size 0.00000 MB" prefix=mempool
time="2019-07-28T05:39:07-04:00" level=trace msg="list of the verified txs" prefix=mempool

[snip]

[jules]

Gotcha, thanks for the info! I'm quite certain the absence of blindbid caused the lockup here, as the block generation component currently immediately generates a first proof on startup. Afterwards it should return and continue in a goroutine, consequently giving back your console, but if it has no blindbid process to communicate with, it gets stuck waiting for a response the first time.

After you've re-built and re-synced your node (in accordance with #4), give it another shot with the blindbid process running and let me know if it still occurs. Would advise removing both chain and walletDB, though you can keep the wallet.dat file.

[Rigorously]

Looks like I missed this crucial line of the README.

If you wish to participate in consensus, it is necessary that you also build and run the blindbid executable, explained below.

You could say I am a bit blind.

[Rigorously]

I am unable to build dusk-blindbidproof because it depends on bulletproofs on the private Gitlab repo.

[jules]

You're right, I'll forward it to the team right away

[jules]

@Rigorously The repo has just been updated - it should work now!

[Rigorously]

I noticed blindbid-avx2 and blindbid-mac are included now. I tried to build it from source too, but it fails on compiling 2 subtle feature attributes with a stable compiler.

Anyway.

• Backed up wallet.dat.
• Deleted everything.

$ go get github.com/dusk-network/dusk-blockchain
$ cd go/src/github.com/dusk-network/dusk-blockchain
$ make (this step is required, but not in the docs)
$ cd launch/testnet
$ ./testnet
> loadwallet [password]
Wallet loaded successfully!
Public Address: [myaddress]
> sync
Syncing wallet... (2716/2716)
Found 0 spends and 0 receives (uh oh)
> balance
Balance: 0.00000000

Of course.

Error! You already submitted a faucet request in the past 24 hours. Please wait before requesting more Dusk.

Alright, something is telling me to take a break for the day.

[Rigorously]

I ran blindbid-avx2 in a separate console in the background and managed to successfully run startprovisioner and startblockgenerator. Control is given back to the user.

I confirm if the user does not have blindbid running and executes startblockgenerator, unlike startprovisioner, control is not given back to the user. In the latter case, an explanation and returning control would be desirable.

[jules]

In the latter case, an explanation and returning control would be desirable.

Agreed, it is hard to understand what is going on at the moment. It is partially due to the use of the named pipe communications between the Rust process and the Go process, which makes it difficult for either process to know if the other is running.

I will adjust the flow of events for startblockgenerator to be more clear, verbose and make sure not to usurp control from the user in the case of no blindbid process running.