Starting preliminary 0.94 testing - "Headless fullnode"

[goatpig]

As for progress, I'll improve the log message with the upcoming fixes.

Thanks. I hope it could be logged by fixed time interval, not by block interval. It would be very helpful for slow machine like mine.

That's a good idea, I'll do that.

[jl2012]

As for progress, I'll improve the log message with the upcoming fixes.

Thanks. I hope it could be logged by fixed time interval, not by block interval. It would be very helpful for slow machine like mine.

That's a good idea, I'll do that.

I have to give up at about block 290000. It takes ~20s to process a block. The worst thing is it freezes the VM

My VM's config:

Host: Hyper-V 2012 R2
OS: Debian jessie
RAM: 29GB
CPU: Intel i5 Quad-core
HD: RAID 1 (non-SSD)

[goatpig]

New version out in ffreeze, please test away. There's a wealth of robustness changes and it should also be a bit faster. However no one at Armory has experienced the issues Carlton Banks and btcchris ran into, so most of these changes were speculative. It's possible these bugs will still be there partially or in full.

As usual, looking forward to your bug reports and logs, and again thank you for the time and effort you put in helping us to test things out =)

[Carlton Banks]

Having trouble getting past this stage in the DB build:

Code:

-INFO  - 1433717171: (BlockUtils.cpp:1337) Looking for first unrecognized block

CPU cores hit the floor, that block never gets found.

[goatpig]

Having trouble getting past this stage in the DB build:

Code:

-INFO  - 1433717171: (BlockUtils.cpp:1337) Looking for first unrecognized block

CPU cores hit the floor, that block never gets found.

Fresh DB folder? Is it maxing one core or all cores?

[Carlton Banks]

Having trouble getting past this stage in the DB build:

Code:

-INFO  - 1433717171: (BlockUtils.cpp:1337) Looking for first unrecognized block

CPU cores hit the floor, that block never gets found.

Fresh DB folder? Is it maxing one core or all cores?

Yes, fresh DB. CPU activity cuts out altogether (occasional 1% blip for python). Logs and gdb output all look uninteresting.

[goatpig]

Having trouble getting past this stage in the DB build:

Code:

-INFO  - 1433717171: (BlockUtils.cpp:1337) Looking for first unrecognized block

CPU cores hit the floor, that block never gets found.

Fresh DB folder? Is it maxing one core or all cores?

Yes, fresh DB. CPU activity cuts out altogether (occasional 1% blip for python). Logs and gdb output all look uninteresting.

This is weird I didn't touch that part of the code. I'll get back to you when it's fixed (hopefully I can reproduce it)

What's the last line in the terminal?

[Carlton Banks]

This is weird I didn't touch that part of the code. I'll get back to you when it's fixed (hopefully I can reproduce it)

It happens to me every time it runs. So far. (4-5 attempts)

What's the last line in the terminal?

Code:

-DEBUG - 1433717168: (Blockchain.cpp:214) Organizing chain w/ rebuild
-INFO  - 1433717171: (BlockUtils.cpp:1337) Looking for first unrecognized block
[New Thread 0x7fffd33f7700 (LWP 5367)]
[Thread 0x7fffd33f7700 (LWP 5367) exited]

Program received signal SIGTERM, Terminated.
0x00007ffff6fd050d in poll () at ../sysdeps/unix/syscall-template.S:81
81	../sysdeps/unix/syscall-template.S: No such file or directory.

The SIGTERM was generated by me, issuing a kill is the only way to get it shut down. This is consistent also.

There is a difference to my setup, in that I'm using jessie instead of wheezy, but I don't think that's the source of the problem. I know, better to keep the setup the same, but it's a long story, and 93.1 works identically on jessie as it does on wheezy.

[goatpig]

There is a difference to my setup, in that I'm using jessie instead of wheezy, but I don't think that's the source of the problem. I know, better to keep the setup the same, but it's a long story, and 93.1 works identically on jessie as it does on wheezy.

It should work on any setup as long as the compiler is doing its job really.

Can you get through with testnet?

[Carlton Banks]

Ok this really is totally consistent behaviour. Tried not rebuilding the Db, just let it carry on from where it hits the (infinite?) loop. The headers get read again (implying the data structure for the headers wasn't committed to disk in the failed run), then it hits the same loop. I could try this with testnet I guess, but that's a fair amount of setup to confirm something so fundamental and consistent.

[goatpig]

Ok this really is totally consistent behaviour. Tried not rebuilding the Db, just let it carry on from where it hits the (infinite?) loop. The headers get read again (implying the data structure for the headers wasn't committed to disk in the failed run), then it hits the same loop. I could try this with testnet I guess, but that's a fair amount of setup to confirm something so fundamental and consistent.

I've reproduced this issue and I'm on it. I've also got a clue on the other one in the process so I may get both by the next commit.

[jl2012]

New version out in ffreeze, please test away. There's a wealth of robustness changes and it should also be a bit faster. However no one at Armory has experienced the issues Carlton Banks and btcchris ran into, so most of these changes were speculative. It's possible these bugs will still be there partially or in full.

As usual, looking forward to your bug reports and logs, and again thank you for the time and effort you put in helping us to test things out =)

Have you made any big change re supernode? In the previous ffreeze it did not complete even with a week. In this version it took only a few hours to complete.

I can now get the details of a random tx with "armoryd.py gettransaction txid". I guess this means the supernode in running properly?

[goatpig]

New version out in ffreeze, please test away. There's a wealth of robustness changes and it should also be a bit faster. However no one at Armory has experienced the issues Carlton Banks and btcchris ran into, so most of these changes were speculative. It's possible these bugs will still be there partially or in full.

As usual, looking forward to your bug reports and logs, and again thank you for the time and effort you put in helping us to test things out =)

Have you made any big change re supernode? In the previous ffreeze it did not complete even with a week. In this version it took only a few hours to complete.

I made changes to some stuff that makes supernode faster (some weird opts I should have rolled but figured it could wait for fear it would be unstable). The other issue, with pulling block data and the object lifespan remains. It's a rare occurrence but common enough to trip certain setup quite often (2 out of my 3 testers T_T). I ended rolled the optimization with the stability changes (it didn't cost that much more to add the opts at that stage)

Now I'm also convinced that the code speeding up supernode is not responsible for the instability. That gives me room to add some more optimizations (again supernode only) without fear of making bugs more convoluted (and thus harder to isolated).

Not having a clue what the issue was, I ended up fixing what you were suffering from (which was a lot more obvious than the remaining issue) in an attempt to fix the bug they are experiencing. In grand scheme of things it doesn't matter what order I fix these, since I have to go after both anyways. In the current scope, it doesn't speak so good of me since I thought I was fixing one thing and got the other instead =P

I can now get the details of a random tx with "armoryd.py gettransaction txid". I guess this means the supernode in running properly?

Not really, that just means you are using supernode indeed (which is the only the DB format now that support random txhash resolution), but that doesn't mean supernode is working per se. What you need to do to test it is to add a random bitcoin address to a wallet and getledger on the wallet, which will display that random address history along with the rest.

You can also verify this in the UI by importing some publicly known private keys to a wallet (kind of an oxymoron I know) and verify they get imported quasi instantly and that their history shows up in the main ledger.

[Roy Badami]

(On OS X)

No errors building the database - but doesn't find any transactions and all wallet balances are 0.0

EDIT: Ah, OK, database appears to build OK judging by progress, but then scanning transactions seems to complete almost instantly (so evidently it actually failed - but didn't give an error).

roy

[goatpig]

(On OS X)

No errors building the database - but doesn't find any transactions and all wallet balances are 0.0

EDIT: Ah, OK, database appears to build OK judging by progress, but then scanning transactions seems to complete almost instantly (so evidently it actually failed - but didn't give an error).

roy

Lemme see the last few lines of your log file. Also, what's the top block displayed in Armory?

[Roy Badami]

Ah, after several restarts of Armory it finally started scanning - made it most of the way there - now has transactions up to late 2014.  There's virtually nothing interesting in armorylog.txt.

I get the following error at startup (which I presume is largely harmless?)

Code:

2015-06-09 20:54 (INFO) -- announcefetch.py:271 - Fetching: https://bitcoinarmory.com/announce.txt
2015-06-09 20:54 (ERROR) -- announcefetch.py:312 - Could not verify data in signed message block
Traceback (most recent call last):
  File "/Users/roy/BitcoinArmory/osxbuild/workspace/Armory.app/Contents/MacOS/py/usr/lib/armory/announcefetch.py", line 304, in __runFetchSequence
    sig, msg = readSigBlock(digestData)
  File "/Users/roy/BitcoinArmory/osxbuild/workspace/Armory.app/Contents/MacOS/py/usr/lib/armory/jasvet.py", line 589, in readSigBlock
    name = r.split(BEGIN_MARKER)[1].split(DASHX5)[0]
IndexError: list index out of range

And apart from that littereally nothing of interest; just a couple of new blocks that came in during the scan:

Code:

2015-06-09 20:57 (INFO) -- ArmoryQt.py:3132 - Current block number: 360187
2015-06-09 20:57 (INFO) -- ArmoryQt.py:6235 - New Block! : 360189
2015-06-09 20:57 (INFO) -- ArmoryQt.py:6243 - Current block number: 360189
2015-06-09 20:59 (INFO) -- Networking.py:215 - Received new block.  0000000000000000141082c80
45e2baded1c074967f0fdf70fb65b3ebb55bd37
2015-06-09 20:59 (INFO) -- ArmoryQt.py:6235 - New Block! : 360190
2015-06-09 20:59 (INFO) -- ArmoryQt.py:6243 - Current block number: 360190
2015-06-09 21:04 (INFO) -- Networking.py:215 - Received new block.  00000000000000000b3c8380aab3c52af2302c8763acff016ad750c3765d7767
2015-06-09 21:04 (INFO) -- ArmoryQt.py:6235 - New Block! : 360191
2015-06-09 21:04 (INFO) -- ArmoryQt.py:6243 - Current block number: 360191
2015-06-09 21:14 (INFO) -- Networking.py:215 - Received new block.  0000000000000000144086516ccc3824128835fbef52eb26e0c0fc81723f0dac
2015-06-09 21:14 (INFO) -- ArmoryQt.py:6235 - New Block! : 360192
2015-06-09 21:14 (INFO) -- ArmoryQt.py:6243 - Current block number: 360192

EDIT: Fixed log paste

[Roy Badami]

Just reran it having removed the database and log files.  Takes about 12 minutes to go through receiving headers, organizing blockchain and building databases - and then goes through the scan transactions phase in well under a minute (and ends up showing no transactions and 0.0 balance).  I'll send you full logs of that run if you let me know the best way to get them to you.

EDIT: Block number displayed in the GUI is correct.

[goatpig]

Gimme the part of the log where it posts the timings after the scan is over. I want to see the last block it scanned.

[Roy Badami]

Ah, interesting.  In armorycpp.log, it looks like it got to around block 130,000 and then readjusted the number of threads.  No more Only one more "finished applying" message after the thread readjust message - which takes it up to block 130,250 (which is before I was using bitcoin - so consistent with the wallets all showing zero balance).

Code:

-WARN  - 1433882811: (BlockUtils.cpp:1071) Scanning from 0 to 360192
-WARN  - 1433882817: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 2500
-WARN  - 1433882819: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 85000
-WARN  - 1433882822: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 105000
-WARN  - 1433882824: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 115000
-WARN  - 1433882828: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 120000
-WARN  - 1433882830: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 125000
-WARN  - 1433882832: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 127500
-WARN  - 1433882838: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 130000
-INFO  - 1433882842: (BlockWriteBatcher.cpp:2067)  &&&&&&&&& cumulatedReadTime: 41.2889s
-INFO  - 1433882842: (BlockWriteBatcher.cpp:2068)  &&&&&&&&& cumulatedWorkTime: 9.8054s
-INFO  - 1433882842: (BlockWriteBatcher.cpp:2069)  &&&&&&&&& cumulatedWriteTime: 0.186015s
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2083) Readjusting thread count: 
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2084) 2 readers
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2085) 1 workers
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2086) 1 writers
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2087) 1 old reader count
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2088) 1 old worker count
-WARN  - 1433882842: (BlockWriteBatcher.cpp:2089) 1 old writer count
-WARN  - 1433882842: (BlockWriteBatcher.cpp:494) Finished applying blocks up to 132500
-WARN  - 1433882844: (BlockWriteBatcher.cpp:503) --- cumulatedBatchSleep: 0
-WARN  - 1433882844: (BlockWriteBatcher.cpp:545) --- feedSleep: 0 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:548) --- workers: 0 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:551) --- writeStxo: 0.004949 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:553) --- writeStxo_grabMutex: 6.9e-05 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:556) --- waitingOnSerThread: 0.123388 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:558) --- waitForDataToWrite: 46.0291 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:562) --- checkForCollisions: 0.00029 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:564) --- getExistingKeys: 0.000519 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:566) --- getNewKeys: 0.002581 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:568) --- getSSHHeadersLock: 5.1e-05 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:570) --- computeDBKeys: 0.00322 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:572) --- getSshHeaders: 0.00015 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:574) --- finalizeSerialization: 0.048598 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:579) --- serializeBatch: 0.099822 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:581) --- updateSSH: 0.008117 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:583) --- serializeSubSsh: 8.6e-05 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:585) --- waitOnSSHser: 0.041361 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:589) --- waitOnWriteThread: 0.001888 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:592) --- putSSH: 0.151328 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:594) --- putSTX: 0.000495 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:597) --- getnextfeed: 22.2412 s
-WARN  - 1433882844: (BlockWriteBatcher.cpp:599) --- inControlThread: 46.3596 s
-INFO  - 1433882844: (BlockUtils.cpp:1451) --- bwbDtor: 0s
-INFO  - 1433882844: (BlockUtils.cpp:1452) Scanned Block range in 46.472s
-INFO  - 1433882844: (BlockUtils.cpp:1455) Finished loading at file 280, offset 31371188
-INFO  - 1433882844: (BlockDataViewer.cpp:155) Enabling zero-conf tracking 
-DEBUG - 1433882844: (Blockchain.cpp:214) Organizing chain 
-INFO  - 1433882844: (BlockUtils.cpp:1489) Loading block data... file 280 offset 31371188
-INFO  - 1433882844: (BlockUtils.cpp:544) Reading raw blocks finished at file 280 offset 32869610
-WARN  - 1433882844: (BlockUtils.cpp:1071) Scanning from 360193 to 360194
-WARN  - 1433882845: (BlockWriteBatcher.cpp:503) --- cumulatedBatchSleep: 0
-WARN  - 1433882845: (BlockWriteBatcher.cpp:545) --- feedSleep: 0 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:548) --- workers: 0 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:551) --- writeStxo: 0.000513 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:553) --- writeStxo_grabMutex: 6e-06 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:556) --- waitingOnSerThread: 0.00268 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:558) --- waitForDataToWrite: 0.339536 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:562) --- checkForCollisions: 4e-06 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:564) --- getExistingKeys: 0.000724 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:566) --- getNewKeys: 4e-06 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:568) --- getSSHHeadersLock: 4e-06 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:570) --- computeDBKeys: 2.7e-05 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:572) --- getSshHeaders: 1.4e-05 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:574) --- finalizeSerialization: 0.006073 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:579) --- serializeBatch: 0.001759 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:581) --- updateSSH: 0.000546 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:583) --- serializeSubSsh: 6e-06 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:585) --- waitOnSSHser: 0.005375 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:589) --- waitOnWriteThread: 5e-06 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:592) --- putSSH: 0.001174 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:594) --- putSTX: 3.7e-05 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:597) --- getnextfeed: 0.292328 s
-WARN  - 1433882845: (BlockWriteBatcher.cpp:599) --- inControlThread: 0.356495 s

Is this thread count adjustment something I can try turning off?

[Roy Badami]

I should also point out that this is my first time building in a very long time (I think the last time was before you offered prebuilt Mac binaries) so in particular I have absolutely no evidence that there isn't something subtly borked in my build environment.