Mar 13, 2018

12 min read

The Debug Log, the Virtual Machine Log, March 13, 2018

Fontana della Barcaccia, Scalinata di Trinità dei Monti, Roma — the debug log — Temple of Ceasar, the Roman Forum

This week we look at the debug.log, and when you suspect problems with your wallet (or if you are just Qtum-curious) the debug.log is your friend. We look at how to find the debug log, how to read it, and how to see problems logged there. The bonus topic is the virtual machine log, vm.log.

I am an independent researcher, occasional blogger, social moderator, and appreciate the technical guidance from the Qtum Team and the discussion/questions in the Community which provide motivation for these reports. If you have any comments or corrections for this report, please reach out on the social medias.

Network Weight, Node Count

From March 4–11, big wallets with known balances of 5.905 million won 709 out of 4,779 block rewards or 14.84%, giving a network weight of 39.8 million, and an annual return for stakers of 2.20%. This calculation uses approximately 11 times the data points and a has better algorithm (IMHO) than the wallet calculation of network weight, but it is a weekly number, while the wallet gives you a new network weight with every block (edited).

The Debug Log File

TL;DR: The debug.log file, in the same Qtum directory as the wallet.dat file, is a text log of basic wallet operations and error conditions. Each log line is written with a UTC time stamp, and shows each new block synced onto the wallet’s blockchain, sends, receives, and error conditions. A companion log for the Qtum virtual machine logs every contract transaction the wallet adds to its blockchain and is a good reference for problem token transactions.

Every time you update the wallet, you could simply rename the debug.log file with today’s date, such as “debug-2018–03–13.log”, which lets you keep the old debug log for reference (or just delete it) and start writing a new debug.log file with the relaunch of the new version wallet. With default settings, the debug.log file saves about 4 MB per week, for qtumd.

Look for the debug.log file in the same directory as the wallet.dat file on your computer. The debug.log file is a plain text file that can be opened with any text editor, or from the QT wallet.

Every log entry starts with a timestamp in UTC (not your local time, no worries about daylight savings time transitions):

This log line says at 14:27:34 UTC on March 7 the wallet processed a block and accepted that block.

I generally grab a copy of the debug.log file while the wallet is running. I’m not sure if this is technically correct but haven’t crashed the wallet yet. The QT wallet offers a handy button in the lower right-hand corner of the Help — Debug window — Information screen to open up the debug.log file.

Perfectly Natural, Perfectly Healthy

We will start with what the debug log shows for normal wallet operations, including wallet startup, normal syncing and sending and receiving operations.

Startup

At startup, the wallet does a lot of work initializing the node software and reads several files, perhaps the most important is the wallet.dat file which contains the wallet’s private keys. After initialization, the wallet will begin making connections to other nodes and begin loading blocks to sync the blockchain. The Qtum Core wallet is a full node and requires a complete copy of the blockchain. The debug log will show the catchup blocks coming in fast, several per second. The wallet will validate each block and write them to its local copy of the blockchain. The entire startup sequence for the example below logged 148 lines. Here are some excerpted highlights, with some lines shortened for clarity, and the yellow highlighting is mine:

After this wallet is initialized, at 18:01:26 it is about half a day (350 blocks) behind the current blockchain height and begins rapidly downloading the missing blocks from other peers. By 18:09:27 the blocks are synced up to date, and normal new block syncing continues.

Below I give an example of the log file for a wallet that can’t connect to peers to sync the blockchain, so sad.

Receiving

Receiving a transaction, the log will show an “AddToWallet” transaction with the transaction ID:

This transaction could be a block reward payment or other receive transaction. The amount is not listed, but you can use the transaction ID to look up the details on your favourite Explorer.

Sending

The log for sending is a little more complex. Here I send 0.2 QTUM; you can see the amount and transaction IDs:

A quick explanation on sending using the Qtum (née bitcoin) Unspent Transaction Output (UTXO) model. The wallet selects an entire previous unspent transaction, in this example an unspent transaction of 1.00000000 QTUM (not shown in the log, but you could see the details in the Explorer). The wallet has to send the entire 1.00000000 transaction, with instructions to give 0.20000000 to a new address and return 0.79909600 back to a change address controlled by the wallet. The difference between the 1.00000000 sent, the 0.20000000 delivered to the receiving address and the 0.79909600 sent back to the change address is 0.00090400:

which the block reward winning wallet knows to keep as a “tip” for publishing the transaction, known as the transaction fee.

Additional Debug Modes

If you wanted to research how the memory pool manages unconfirmed transactions you could use the “-mempool” switch when launching the wallet to log additional debug logging details about the mempool. The options for additional debug categories are:

I’ll leave as an exercise for you to explore what interesting log lines these categories yield, the “miner” switch looks especially juicy.

When Bad Things Happen to Good Wallets

If your wallet is having problems, then you might get some troubleshooting ideas from error reports in the debug.log file, because the debug file is your friend.

1. Loss of network connection

Here a Testnet wallet was happily syncing new blocks up to #99,479 when the wallet lost its internet connection when someone “accidently” disconnected the Ethernet cable. 8 peer connections were forcibly closed (sounds painful) starting at 20:46:46 (some lines shortened for clarity):

After 19 minutes the internet connection was restored at 21:03:09, but the current block was #99,485 (the wallet was 6 blocks behind) and the wallet began rapidly syncing blocks 99480, 99481, 99482, 99483, etc. If you see these “forcibly closed” messages in your debug.log file you should definitely have a conversation with your Internet service provider.

2. Someone’s Clock not set correctly

I have been telling people to set their clocks correctly on the social medias, but now think this is more of a problem for the other wallets. The time reference for the wallet is fairly forgiving, the wallet collects time references from all the peers it connects with and cross checks against local time. The time reference in Qtum (inherited from bitcoin) is quite flexible, and the QT wallet will complain bitterly if you launch it with a bad time (not so sure about qtumd). If your computer time zone and clock is set correctly you can do a “getinfo” command and see “timeoffset” near zero.

If you are running the qtumd server wallet, it can connect with many peers and will definitely find some blocks with bad timestamps, logging “block timestamp too far in the future”. Bad luck for those wallets that successfully mine a new block but then screw up the time reference. The debug.log will show 10 to 20, or more, of the same bad block relayed by other peers, below is the same bad block from 4 nodes (log lines shortened for clarity):

There is quite a bit of chatter logged by qtumd about bad behavior on the network. You can think of your wallet as a fair but ruthless admin in a rowdy chat room (shout-out to Tony Sydney), who has to reject, delete and ban users for inappropriate messages. The wallet has to ban nodes, disconnect other nodes that are not behaving, and reject blocks with bad headers. Your wallet, and every other wallet is an admin 24/7 in the node “chat room” we know as the Qtum Mainnet Ignition network.

3. Wallet Not Syncing Blocks

I’ll be honest, it was hard to get my wallet to not connect to the network by trying to block it through the firewall; the wallet always kept punching through. Finally, I messed up the networking in the wallet so it couldn’t connect to other peers to get this startup debug log file. The wallet logged 77 lines and the debug log simply stopped after “dnsseed thread exit”, and no blocks were synced.

Bonus Logging Topic: The Virtual Machine

Every node processes every contract transaction onto their local copy of the blockchain. When the node validates a new block that contains contract transactions, it indexes into the blockchain to the block where the contract is stored and processes those contract transactions. The node logs results of those contract transactions into the virtual machine log vm.log.

You can find the vm.log file in the Qtum folder, along with wallet.dat and debug.log. The vm.log file is terse. It lists the transaction time in UTC and the contract address. If there is a failure, and the contract transaction failed, the cause will be logged right above the time and address.

Good Transactions

Here are some good contract transactions, as logged in vm.log:

How to read this: The log line will usually be some seconds before the Explorer time stamp which displays on 16-second boundaries. The 24 hour UTC time 12:49:54 references block 112,818 with Explorer time stamp of 12:49:52 pm UTC. The contract address 57931faffdec114056a49adfcaa1caac159a1a25 is where the SpaceCash (SpaceChain) smart contract lives on the blockchain, so we know our wallet processed the transaction for an SPC token transfer, and we can look at block 112,818 to see that someone transferred 3,960 SPC tokens:

Your blogger is a firm believer in watching crypto transactions go through on the Explorer, and always starting with a small test amount. How could that work for a token transfer?

Suppose you were the proud recipient of a recent air drop. You have added the QRC20 token to your wallet, and now you are ready to send a token transaction. You know from a previous blog that all token transactions work by sending the transaction to the smart contract, and you can watch the smart contract transactions executing, including yours.

You view the contract transactions page and watch your small test transaction go through when you send a few tokens from your wallet. After confirming the transaction went through to the smart contract, without changing anything else with your wallet, you can now confidently send the rest of your token transaction.

live transactions for the smart contract

But suppose bad things happen to good wallets and your test transaction doesn’t execute?

Not So Good

Here are some problem transactions logged in vm.log:

How to read this. In the first transaction at 06:30:16, the smart contract ran out of gas before executing the transaction. Someone set the gas too low, so they lose that gas and get the opportunity to try again.

In the second example at 10:05:39, the contract reported a bad instruction. I haven’t analyzed these kinds of failures, but think they could result if you try to make a purchase after an ICO has sold out.

For contract calls that fail, the Explorer will show blank information for that transaction (no token name, no amount transferred), but as far as I know, vm.log is the only way to figure out why a contract transaction failed. If you are having problems with token transfers, the virtual machine log is also your friend.

We finish the blog today in Rome, the eternal city. Ides of March is on March 15 in two days, but I didn’t want to wait to publish this blog. According to the Nodemap Italy is the home of 6 Qtum nodes including one in Rome. Qtum is really worldwide (and at least one low earth orbit satellite) — why not celebrate Rome for its history, cosmopolitan culture and Qtum node?