BUG SOLVED: C2, A2 Confirmation Actions are always lost due to "msg":"Failed to handle tx : broadcast: Node inactive"

In Tokenized Release v 1.0.1 with Bitcoin 1.0.7.1, in every build --tx --send of C1 or A1 I try, it always loses the C2 or A2. Note that 1.0.7.1 is important at least for me to have because it seems to have improved the other issue in 1.0.7 of never finding any peers for the client or just 1 peer, and not too many in the daemon either, around 10 in the daemon. Now in 1.0.7.1 it finds many 10s of peers.
Here is the log showing the loss of A2:
{“level”:“info”,“ts”:1619322668.862994,“caller”:“spynode/node.go:410”,“msg”:“Stopping”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.934015,“caller”:“spynode/node.go:394”,“msg”:“Monitor untrusted finished”,“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322671.979837,“caller”:“listeners/listener.go:86”,“msg”:“Handling tx”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“verbose”,“ts”:1619322671.983225,“caller”:“transactions/storage.go:32”,“msg”:“Adding tx : de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“verbose”,“ts”:1619322671.986187,“caller”:“transactions/storage.go:68”,“msg”:“Adding tx state : de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“info”,“ts”:1619322671.989157,“caller”:“listeners/incoming.go:77”,“msg”:“Tx added to incoming : de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“info”,“ts”:1619322671.992177,“caller”:“listeners/listener.go:136”,“msg”:“Tx confirm”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“info”,“ts”:1619322671.994787,“caller”:“listeners/incoming.go:86”,“msg”:“Processing incoming tx”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“info”,“ts”:1619322671.997472,“caller”:“listeners/incoming.go:132”,“msg”:“Marking tx preprocessed : de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“info”,“ts”:1619322672.000432,“caller”:“listeners/listener.go:137”,“msg”:“Tx confirm”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”,“block_hash”:“00000000000000000150628159bbdbdb9a29fdf894f6de2d1c4360b067dee1da”}
{“level”:“verbose”,“ts”:1619322672.005167,“caller”:“listeners/incoming.go:259”,“msg”:“Marking tx confirmed : de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“verbose”,“ts”:1619322672.010091,“caller”:“listeners/incoming.go:272”,“msg”:“Adding tx to ready : de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“verbose”,“ts”:1619322672.014752,“caller”:“listeners/incoming.go:162”,“msg”:“Pending tx added to processing : de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“verbose”,“ts”:1619322672.017326,“caller”:“listeners/incoming.go:176”,“msg”:“Removing 1 txs from ready”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“verbose”,“ts”:1619322672.019961,“caller”:“listeners/incoming.go:178”,“msg”:“Removing tx from ready : de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“info”,“ts”:1619322672.022522,“caller”:“listeners/processing.go:20”,“msg”:“Processing tx”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“info”,“ts”:1619322672.025461,“caller”:“listeners/processing.go:56”,“msg”:“Request for contract 1BHqQkMpHgTa8kMj9YwMbS7XzZ3w5uUKws”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“info”,“ts”:1619322672.028387,“caller”:“spynode/blocks.go:450”,“msg”:“Processed block : 00000000000000000150628159bbdbdb9a29fdf894f6de2d1c4360b067dee1da : 3631.442 ms”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322672.030793,“caller”:“spynode/node.go:384”,“msg”:“Check tx delays finished”,“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322672.033203,“caller”:“listeners/processing.go:103”,“msg”:“Triggering response”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“verbose”,“ts”:1619322672.035588,“caller”:“spynode/node.go:370”,“msg”:“Process blocks finished”,“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322672.038295,“caller”:“contract/oracles.go:18”,“msg”:“Expanding 0 oracle public keys”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“info”,“ts”:1619322672.040681,“caller”:“handlers/asset.go:141”,“msg”:“Accepting asset creation request : 1BHqQkMpHgTa8kMj9YwMbS7XzZ3w5uUKws 9385d8853ab44b10fab8c15a0f07051189a678a3”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“verbose”,“ts”:1619322672.043638,“caller”:“transactions/storage.go:32”,“msg”:“Adding tx : de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“info”,“ts”:1619322672.046722,“caller”:“node/response.go:251”,“msg”:“Responding with tx : ec52f874447893ae286df40c4ff6529e3e3dd5939a12fab4b13b7917d5d3f47c”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“verbose”,“ts”:1619322672.049456,“caller”:“transactions/storage.go:32”,“msg”:“Adding tx : ec52f874447893ae286df40c4ff6529e3e3dd5939a12fab4b13b7917d5d3f47c”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}
{“level”:“info”,“ts”:1619322672.051949,“caller”:“spynode/node.go:560”,“msg”:“Broadcasting tx : ec52f874447893ae286df40c4ff6529e3e3dd5939a12fab4b13b7917d5d3f47c”,“subsystem”:“SpyNode”}

{“level”:“error”,“ts”:1619322672.054449,“caller”:“listeners/processing.go:110”,“msg”:“Failed to handle tx : broadcast: Node inactive”,“trace”:“de5c4413423113070215d3e7a58fa23d9a4f26cfb88a5bef80dabec14837bb78”}

{“level”:“info”,“ts”:1619322672.064184,“caller”:“spynode/node.go:437”,“msg”:“Incoming threads stopped”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322672.066996,“caller”:“spynode/node.go:377”,“msg”:“Process unconfirmed txs finished”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322672.069586,“caller”:“spynode/node.go:363”,“msg”:“Send outgoing finished”,“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322672.167066,“caller”:“spynode/node.go:457”,“msg”:“Processing threads stopped”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322672.169830,“caller”:“spynode/node.go:460”,“msg”:“Saving”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322672.172837,“caller”:“storage/transactions.go:80”,“msg”:“Saving 1 unconfirmed txs”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322672.175794,“caller”:“storage/peers.go:202”,“msg”:“Saving 60 peers”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322672.178400,“caller”:“spynode/node.go:471”,“msg”:“Restarting”,“subsystem”:“SpyNode”}

The first log entry there says the spynode is stopping. So it is not in a state to broadcast transactions. Is there something before that to specify why it is stopping? smart-contract should definitely not be trying to process a transaction while spynode is stopping, but there seems to be some direct conflict that is stopping spynode at the same time it is receiving this tx.

Here is a chunk of the log before that point:
I do not have any other ideas about any possible conflicting process running.
This is pretty much the same code I have run many times successfully a few months ago
on the prior Tokenized releases.

{“level”:“verbose”,“ts”:1619322667.754886,“caller”:“spynode/node.go:460”,“msg”:“Saving”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322667.757866,“caller”:“storage/transactions.go:80”,“msg”:“Saving 1 unconfirmed txs”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322667.761034,“caller”:“storage/peers.go:202”,“msg”:“Saving 60 peers”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322667.763853,“caller”:“spynode/node.go:471”,“msg”:“Restarting”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322667.770940,“caller”:“spynode/node.go:329”,“msg”:“Re-connecting to 127.0.0.1:8333”,“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322667.774061,“caller”:“listeners/listener.go:25”,“msg”:“SpyNode registration accepted”,“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322667.777093,“caller”:“spynode/node.go:222”,“msg”:“Subscribing to contracts”,“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322667.779682,“caller”:“spynode/node.go:960”,“msg”:“Safe tx delay : 2000 ms”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322667.782435,“caller”:“handlers/version.go:31”,“msg”:"(127.0.0.1:8333) Version : /Bitcoin SV:1.0.7.1/ protocol 70015, blocks 684394",“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322667.785046,“caller”:“listeners/listener.go:38”,“msg”:“Subscribing to 1 addresses”,“subsystem”:“SpyNode”}
{“level”:“warn”,“ts”:1619322667.787641,“caller”:“listeners/listener.go:46”,“msg”:“Message count zero”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322667.790397,“caller”:“spynode/node.go:869”,“msg”:“Requesting headers”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322667.793266,“caller”:“spynode/node.go:794”,“msg”:“ReadMessage : Unknown Command : protoconf”,“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322667.795844,“caller”:“state/state.go:49”,“msg”:“Saving Spynode next message ID : 1”,“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322667.804585,“caller”:“listeners/listener.go:76”,“msg”:“SpyNode client ready at next message 1”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322667.808680,“caller”:“spynode/node.go:930”,“msg”:“Requesting headers after : 0000000000000000021c460f443c9dfdf98435a4386026ec1d1a9608e9de08d8”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.214191,“caller”:“handlers/block.go:51”,“msg”:“Received block : 00000000000000000150628159bbdbdb9a29fdf894f6de2d1c4360b067dee1da”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.217414,“caller”:“handlers/headers.go:114”,“msg”:“Header (not next) : 000000000000000006f318b9a5aea0d928472185d8456e4a21fd07861d54edfe”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.220256,“caller”:“handlers/headers.go:114”,“msg”:“Header (not next) : 00000000000000000150628159bbdbdb9a29fdf894f6de2d1c4360b067dee1da”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.225591,“caller”:“spynode/node.go:930”,“msg”:“Requesting headers after : 0000000000000000021c460f443c9dfdf98435a4386026ec1d1a9608e9de08d8”,“subsystem”:“SpyNode”}
:
:
{“level”:“verbose”,“ts”:1619322668.437907,“caller”:“handlers/headers.go:114”,“msg”:“Header (not next) : 00000000000000000150628159bbdbdb9a29fdf894f6de2d1c4360b067dee1da”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.466008,“caller”:“spynode/node.go:930”,“msg”:“Requesting headers after : 0000000000000000021c460f443c9dfdf98435a4386026ec1d1a9608e9de08d8”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.493339,“caller”:“handlers/headers.go:114”,“msg”:“Header (not next) : 000000000000000006f318b9a5aea0d928472185d8456e4a21fd07861d54edfe”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.514478,“caller”:“handlers/headers.go:114”,“msg”:“Header (not next) : 00000000000000000150628159bbdbdb9a29fdf894f6de2d1c4360b067dee1da”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.543260,“caller”:“spynode/node.go:930”,“msg”:“Requesting headers after : 0000000000000000021c460f443c9dfdf98435a4386026ec1d1a9608e9de08d8”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.566091,“caller”:“handlers/headers.go:114”,“msg”:“Header (not next) : 000000000000000006f318b9a5aea0d928472185d8456e4a21fd07861d54edfe”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.591778,“caller”:“handlers/headers.go:114”,“msg”:“Header (not next) : 00000000000000000150628159bbdbdb9a29fdf894f6de2d1c4360b067dee1da”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.615675,“caller”:“spynode/node.go:930”,“msg”:“Requesting headers after : 0000000000000000021c460f443c9dfdf98435a4386026ec1d1a9608e9de08d8”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.643608,“caller”:“handlers/headers.go:114”,“msg”:“Header (not next) : 000000000000000006f318b9a5aea0d928472185d8456e4a21fd07861d54edfe”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.655517,“caller”:“handlers/headers.go:114”,“msg”:“Header (not next) : 00000000000000000150628159bbdbdb9a29fdf894f6de2d1c4360b067dee1da”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.665895,“caller”:“spynode/node.go:930”,“msg”:“Requesting headers after : 000000000000000006f318b9a5aea0d928472185d8456e4a21fd07861d54edfe”,“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322668.670580,“caller”:“listeners/listener.go:164”,“msg”:“New headers (1) to height 683939 : 00000000000000000150628159bbdbdb9a29fdf894f6de2d1c4360b067dee1da”}
{“level”:“verbose”,“ts”:1619322668.673436,“caller”:“spynode/blocks.go:260”,“msg”:“Processing block 683939 (2186 tx) : 00000000000000000150628159bbdbdb9a29fdf894f6de2d1c4360b067dee1da”,“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322668.676028,“caller”:“handlers/headers.go:59”,“msg”:“Headers in sync at height 683939”,“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322668.687720,“caller”:“handlers/headers.go:66”,“msg”:“Blocks in sync at height 683939”,“subsystem”:“SpyNode”}
{“level”:“warn”,“ts”:1619322668.723451,“caller”:“spynode/node.go:798”,“msg”:“SpyNodeFailed : ReadMessage : Connection Closed : EOF”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.736573,“caller”:“spynode/node.go:527”,“msg”:“Requesting stop”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.750161,“caller”:“spynode/node.go:349”,“msg”:“Monitor incoming finished”,“subsystem”:“SpyNode”}
{“level”:“verbose”,“ts”:1619322668.859620,“caller”:“spynode/node.go:356”,“msg”:“Monitor request timeouts finished”,“subsystem”:“SpyNode”}
{“level”:“info”,“ts”:1619322668.862994,“caller”:“spynode/node.go:410”,“msg”:“Stopping”,“subsystem”:“SpyNode”}

It looks like your bitcoind node is disconnecting spynode. It had just barely connected and requested some headers, then bitcoind closed the connection. Maybe it was having issues at the time, or you need to whitelist yourself. I know there was a recent change to bitcoind that disconnects you if you were not whitelisted and requested the mempool like spynode does.

I need to add an option to not request the mempool and also harden smart contract to not attempt to process a transaction when in that state.

If you use the current latest version on the develop branch and set the config value REQUEST_MEMPOOL to false, then it should fix the constant reconnect issue with your bitcoind node.

If you confirm that it works for you I will make a release on the master branch.

Is there a downside to not requesting MEMPOOL?
What does requesting MEMPOOL do for spynode?

Requesting the mempool helps spynode get a more accurate mempool faster and see more of the unconfirmed transactions faster. It is not really necessary.

Since BSV is healthy, transactions don’t really hang out in the mempool for more than a block or two, so after that spynode will be up to date without requesting the mempool.

Spynode is designed to be always on, so it is not expected to have full double spend detection until it has been running for a while anyway, which is the main thing the mempool is used for.

OK the code on the Develop branch worked,
And I added
export REQUEST_MEMPOOL=false
to the .env file for the daemon.

I got my A1 and A2 onto the blockchain.
Thank you.