Following the Advanced Example Fails on Transaction

[RhettCreighton]

rhett@w530 ~/projects/grin $ RUST_BACKTRACE=1 RUST_LOG=grin=debug grin wallet -p "password" -a "http://127.0.0.1:20001" send 20000 -d "http://127.0.0.1:35000"
INFO:grin: Using configuration file at: /home/rhett/projects/grin/grin.toml
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: NotEnoughFunds(20000)', /checkout/src/libcore/result.rs:859
stack backtrace:
   0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace
             at /checkout/src/libstd/sys/unix/backtrace/tracing/gcc_s.rs:49
   1: std::sys_common::backtrace::_print
             at /checkout/src/libstd/sys_common/backtrace.rs:71
   2: std::panicking::default_hook::{{closure}}
             at /checkout/src/libstd/sys_common/backtrace.rs:60
             at /checkout/src/libstd/panicking.rs:355
   3: std::panicking::default_hook
             at /checkout/src/libstd/panicking.rs:371
   4: std::panicking::rust_panic_with_hook
             at /checkout/src/libstd/panicking.rs:549
   5: std::panicking::begin_panic
             at /checkout/src/libstd/panicking.rs:511
   6: std::panicking::begin_panic_fmt
             at /checkout/src/libstd/panicking.rs:495
   7: rust_begin_unwind
             at /checkout/src/libstd/panicking.rs:471
   8: core::panicking::panic_fmt
             at /checkout/src/libcore/panicking.rs:69
   9: core::result::unwrap_failed
             at /checkout/src/libcore/macros.rs:29
  10: <core::result::Result<T, E>>::unwrap
             at /checkout/src/libcore/result.rs:737
  11: grin::wallet_command
             at ./src/bin/grin.rs:376
  12: grin::main
             at ./src/bin/grin.rs:227
  13: __rust_maybe_catch_panic
             at /checkout/src/libpanic_unwind/lib.rs:98
  14: std::rt::lang_start
             at /checkout/src/libstd/panicking.rs:433
             at /checkout/src/libstd/panic.rs:361
             at /checkout/src/libstd/rt.rs:57
  15: main
  16: __libc_start_main
  17: _start

[ignopeverell]

Did you have anything mined prior to that? Most likely issue is you really have "NotEnoughFunds" with nothing to spend in your wallet.

[RhettCreighton]

I previously ran a wallet with:

rhett@w530 ~/projects/grin $ RUST_LOG=grin=info grin wallet -p "password" -r 15000 receive
INFO:grin: Using configuration file at: /home/rhett/projects/grin/grin.toml
INFO:grin: Starting the Grin wallet receiving daemon at 127.0.0.1:15000...
INFO:grin_api::rest: route: POST /v1/receive/coinbase
INFO:grin_api::rest: route: POST /v1/receive/receive_json_tx

and a mining sever with:

RUST_LOG=grin=info grin server -m -p 10000 -a 10001 -w "http://127.0.0.1:15000" run

at block 7 in this case:

INFO:grin_grin::miner: (Server ID: Port 10000) Found valid proof of work, adding block ecff0241.
INFO:grin_chain::pipe: Starting validation pipeline for block ecff0241 at 7 with 0 inputs and 1 outputs.
INFO:grin_chain::pipe: Updated head to ecff0241 at 7.
INFO:grin_chain::pipe: Starting validation pipeline for block 2f154e68 at 8 with 0 inputs and 1 outputs.

[RhettCreighton]

strange, my wallet.dat is empty:

rhett@w530 ~/projects/grin $ cat wallet.dat 
{
  "outputs": []
}

[ignopeverell]

I believe @antiochp made a few recent updates there, maybe a little bug?

[antiochp]

Hmm - I think the current grin.toml config file has got -

burn_reward = true

You'll need to set that to false to have the mining node send coinbase to the wallet.

[marzig76]

@antiochp, I took your advice and set burn_reward = false, but I'm getting the same error as @heyrhett.

When I run grin wallet info (with my password), I get:

Outputs - 
fingerprint, n_child, height, lock_height, status, value
----------------------------------
fd997546, 1, 0, 0, Unconfirmed, 1000000000

No matter how long I keep my miner running, that status never changes to confirmed, and the height never increases beyond 0.

[antiochp]

I suspect the docs may need updating and that specifying various ports is not quite right in the docs.

The following works for me on a clean build (just using default ports etc.) -

# start the wallet receiver on default ports
grin wallet -p "password" receive

# start the mining node on default ports
grin server run 

# wallet info on default ports
grin wallet -p "password" info

Eventually producing something like -

Outputs - 
fingerprint, n_child, height, lock_height, status, value
----------------------------------
fd997546, 1, 1, 4, Immature, 1000000000
15d2f09b, 2, 0, 0, Unconfirmed, 1000000000

I just diff'd my grin.toml and these are the only config settings that differ from the version in git -

#mining_parameter_mode = "Production"
mining_parameter_mode = "UserTesting"

#enable_mining = false 
enable_mining = true

#burn_reward = true
burn_reward = false 

[antiochp]

I'm also definitely seeing situations where starting up the mining node for the first time in a clean dir causes it to apparently get stuck, no blocks ever get found and it just sits there in the event loop -

DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running

Stopping and restarting the mining node does seem to resolve this.

The mining side of things is pretty much a black box for me. Maybe @yeastplume has more info/insight here?

[yeastplume]

Can you post the entire log from one of those runs?

[yeastplume]

Also, that's what's output when enable_mining is set to false in grin.toml. I changed that on the last PR, as I wanted to encourage people to at least have a cursory look at the mining parameters in the config file before mining.

[antiochp]

Hey @yeastplume logs from the node here - https://gist.github.com/antiochp/12e64dda50335a9aee1d636456699ae6 Mining is definitely enabled.

[yeastplume]

It works on my machine, so there is no issue. QED

Seriously, I'm at block 80 and counting on a new chain without seeing that issue. What OS is this running on? It's odd to see it just stopping, cause generally issues within the plugins themselves will result in an assertion or outright segfault.

I'm also not generally sending around transactions when testing mining, so that may have something to do with it. edit: I see those are just wallet info commands.. testing as well getting the wallet info every now and then.. no issues.

[antiochp]

This is macOS. I can take a look and see if I can reproduce this or not on Linux (presumably not).

[pfolthof]

Just wanted to add that with a completely clean build, I have the same on macOS High Sierra (I also removed rust and cargo + reinstalled, no changes to the config / build scripts):

PFs-iMac:grin pfolthof$ RUST_LOG=grin=info target/debug/grin wallet -p "password" receive
INFO:grin: Using configuration file at: /Users/pfolthof/Develop/grin/grin.toml
INFO:grin: Starting the Grin wallet receiving daemon at 127.0.0.1:13416...
INFO:grin_api::rest: route: POST /v1/receive/coinbase
INFO:grin_api::rest: route: POST /v1/receive/receive_json_tx

Then in directory node1 in a second shell (only copied grin.toml):

PFs-iMac:node1 pfolthof$ RUST_LOG=grin=debug ../target/debug/grin server -m run
INFO:grin: Using configuration file at: /Users/pfolthof/Develop/grin/node1/grin.toml
INFO:grin: Starting the Grin server...
INFO:grin_pow: Starting miner loop for Genesis Block
INFO:grin_pow::plugin: Mining plugin 0 - /Users/pfolthof/Develop/grin/node1/../target/debug/plugins/mean_compat_cpu_16.cuckooplugin
INFO:grin_chain::chain: Saved genesis block with hash 14b308ba
DEBUG:grin_grin::sync: Starting syncer.
WARN:grin_p2p::server: P2P server started on 127.0.0.1:13414
INFO:grin_grin::server: Starting rest apis at: 127.0.0.1:13413
WARN:grin_grin::server: Grin server started.
INFO:grin_grin::miner: (Server ID: Port 13414) Starting miner loop.
DEBUG:grin_pow::plugin: Not re-loading plugin or directory.
DEBUG:grin_grin::miner: in miner loop...
INFO:grin_api::rest: route: GET /v1/chain/:id
INFO:grin_api::rest: route: GET /v1/chain/utxo/:id
INFO:grin_api::rest: route: GET /v1/pool/:id
INFO:grin_api::rest: route: POST /v1/pool/push
DEBUG:grin_grin::miner: (Server ID: Port 13414) Built new block with 0 inputs and 1 outputs, difficulty: 10
DEBUG:grin_grin::miner: (Server ID: Port 13414) Mining at Cuckoo16 for 90 secs (will wait for last solution) on block 14b308ba at difficulty 10.
Plugin 0 - Device 0 (CPU) - Last Solution time: 0.001; Solutions per second: 1000.000
Plugin 0 - Device 0 (CPU) - Last Solution time: 0.002; Solutions per second: 500.000
Plugin 0 - Device 0 (CPU) - Last Solution time: 0.001; Solutions per second: 1000.000
Plugin 0 - Device 0 (CPU) - Last Solution time: 0.001; Solutions per second: 1000.000
INFO:grin_grin::miner: (Server ID: Port 13414) Found valid proof of work, adding block ea97c647.
INFO:grin_chain::pipe: Starting validation pipeline for block ea97c647 at 1 with 0 inputs and 1 outputs.
DEBUG:grin_chain::pipe: Validating block with cuckoo size 16
DEBUG:grin_chain::pipe: Block at 1 with hash ea97c647 is valid, going to save and append.
INFO:grin_chain::pipe: Updated head to ea97c647 at 1.
DEBUG:grin_grin::miner: resetting pubkey in miner to None
DEBUG:grin_grin::miner: in miner loop...
DEBUG:grin_grin::miner: (Server ID: Port 13414) Built new block with 0 inputs and 1 outputs, difficulty: 10
DEBUG:grin_grin::miner: (Server ID: Port 13414) Mining at Cuckoo16 for 90 secs (will wait for last solution) on block ea97c647 at difficulty 10.
Plugin 0 - Device 0 (CPU) - Last Solution time: 0.001; Solutions per second: 1000.000
INFO:grin_grin::miner: (Server ID: Port 13414) Found valid proof of work, adding block 6f0de658.
INFO:grin_chain::pipe: Starting validation pipeline for block 6f0de658 at 2 with 0 inputs and 1 outputs.
DEBUG:grin_chain::pipe: Validating block with cuckoo size 16
DEBUG:grin_chain::pipe: Block at 2 with hash 6f0de658 is valid, going to save and append.
INFO:grin_chain::pipe: Updated head to 6f0de658 at 2.
DEBUG:grin_grin::miner: resetting pubkey in miner to None
DEBUG:grin_grin::miner: in miner loop...
DEBUG:grin_grin::miner: (Server ID: Port 13414) Built new block with 0 inputs and 1 outputs, difficulty: 10
DEBUG:grin_grin::miner: (Server ID: Port 13414) Mining at Cuckoo16 for 90 secs (will wait for last solution) on block 6f0de658 at difficulty 10.
Plugin 0 - Device 0 (CPU) - Last Solution time: 0.001; Solutions per second: 1000.000
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running
DEBUG:grin_grin::server: event loop running

Somewhat unrelated (so might need another post); I was wondering if GPU mining is CUDA (NVIDIA) only or if OpenCL (AMD) is planned?

[antiochp]

I suspect the mining run_loop thread is dying silently on macOS somehow. Once it gets into that series of event loop running debug logs it does not appear to ever recover.

[yeastplume]

Probably correct the thread is dying somehow... okay I'm able to reproduce here, so I should be able to get to the bottom of this.

[yeastplume]

Would anyone having this issue mind trying the following:

in pow/Cargo.toml change

tag="grin_integration_13"

to

tag="barrier_test"

Build, and see if the issue is still occurring?

[antiochp]

@yeastplume just tested with tag="barrier_test" I have tried a few times from a clean node dir and cannot reproduce the issue with this tag.

[pfolthof]

I agree, with tag="barrier_test" and latest code it keeps running:

Plugin 0 - Device 0 (CPU) - Last Solution time: 0.001; Solutions per second: 1000.000
Plugin 0 - Device 0 (CPU) - Last Solution time: 0.004; Solutions per second: 250.000
INFO:grin_grin::miner: (Server ID: Port 13414) Found valid proof of work, adding block a25bcc74.
INFO:grin_chain::pipe: Starting validation pipeline for block a25bcc74 at 116 with 0 inputs and 1 outputs.
DEBUG:grin_chain::pipe: Validating block with cuckoo size 16
DEBUG:grin_chain::pipe: Block at 116 with hash a25bcc74 is valid, going to save and append.
INFO:grin_chain::pipe: Updated head to a25bcc74 at 116.
DEBUG:grin_grin::miner: resetting pubkey in miner to None
DEBUG:grin_grin::miner: in miner loop...
DEBUG:grin_grin::miner: (Server ID: Port 13414) Built new block with 0 inputs and 1 outputs, difficulty: 27
DEBUG:grin_grin::miner: (Server ID: Port 13414) Mining at Cuckoo16 for 90 secs (will wait for last solution) on block a25bcc74 at difficulty 27.

[yeastplume]

Okay, I'll include this fix in the next PR, and opened an issue here to track (as even though there's a fix, it would be better to get to the root cause): https://github.com/mimblewimble/cuckoo-miner/issues/12

@ignopeverell I think you can close this issue now, as it's gone well outside the original scope.