[Dev] Feathercoin 0.9.6.2 * Maintenance fix, build & upgrade issues notes.

wrapper

Remaining Debug Output :

2017-08-12 11:53:42 No coin database inconsistencies in last 289 blocks (484 transactions)
2017-08-12 11:53:42 init message: Checking ACP …
2017-08-12 11:53:42 block index 14099ms
2017-08-12 11:53:42 init message: Loading wallet…
2017-08-12 11:53:43 nFileVersion = 90602
2017-08-12 11:53:43 Keys: 0 plaintext, 0 encrypted, 149 w/ metadata, 0 total
2017-08-12 11:53:43 wallet 209ms
2017-08-12 11:53:43 init message: Loading addresses…
2017-08-12 11:53:28 Feathercoin version v0.9.6.2-ftcit-Standard (2017-07-14 17:27:25 +0200)
2017-08-12 11:53:28 Using OpenSSL version OpenSSL 1.0.2g 1 Mar 2016
2017-08-12 11:53:28 Using BerkeleyDB version Berkeley DB 5.3.28: (September 9, 2013)
2017-08-12 11:53:28 Default data directory /home/wrapper/.feathercoin
2017-08-12 11:53:28 Using data directory /home/wrapper/.feathercoin
2017-08-12 11:53:28 Using at most 125 connections (1024 file descriptors available)
2017-08-12 11:53:28 Using 8 threads for script verification
2017-08-12 11:53:28 Using wallet wallet.dat
2017-08-12 11:53:28 init message: Verifying wallet…
2017-08-12 11:53:28 init message: Loading block index…
2017-08-12 11:53:42 LoadBlockIndexDB(): synchronized checkpoint 12a765e31ffd4059bada1e25190f6e98c99d9714d334efa41a195a7e7e04bfe2
2017-08-12 11:53:42 init message: Verifying blocks…
2017-08-12 11:53:42 pindex->GetBlockHash()=27194dbff22fde7e4c1552ac82d3e610e405a65d2236d2ebbfa42a7565229b2a
2017-08-12 11:53:42 view.GetBestBlock()=27194dbff22fde7e4c1552ac82d3e610e405a65d2236d2ebbfa42a7565229b2a
2017-08-12 11:53:43 Loaded 10230 addresses from peers.dat 43ms
2017-08-12 11:53:43 mapBlockIndex.size() = 1089184
2017-08-12 11:53:43 nBestHeight = 1089183
2017-08-12 11:53:43 setKeyPool.size() = 100
2017-08-12 11:53:43 mapWallet.size() = 21
2017-08-12 11:53:43 mapAddressBook.size() = 45
2017-08-12 11:53:43 init message: Done loading
2017-08-12 11:53:43 Initialization result: 1
2017-08-12 11:53:45 GetMyExternalIP() returned xxx.xxx.xxx.xxx
2017-08-12 11:53:45 AddLocal(xxx.xxx.xxx.xxx:9336,4)
2017-08-12 11:53:45 ext-ip thread exit
2017-08-12 11:53:54 dnsseed thread exit

wrapper

Re: LoadBlockIndexDB(): synchronized checkpoint 12a765e31ffd4059bada1e25190f6e98c99d9714d334efa41a195a7e7e04bfe2

**main.cpp - Line 3544

// ppcoin: load hashSyncCheckpoint
if (!pblocktree->ReadSyncCheckpoint(hashSyncCheckpoint))
	 LogPrintf("LoadBlockIndexDB(): synchronized checkpoint not read\n");
else
	 LogPrintf("LoadBlockIndexDB(): synchronized checkpoint %s\n", hashSyncCheckpoint.ToString().c_str());

Original code

if (!pblocktree->ReadSyncCheckpoint(hashSyncCheckpoint))
	 LogPrintf("LoadBlockIndexDB(): synchronized checkpoint not read\n");
else
     if (fDebug)
     	 LogPrintf("LoadBlockIndexDB(): synchronized checkpoint %s\n", hashSyncCheckpoint.ToString().c_str());

wrapper

Re: pindex->GetBlockHash() and view.GetBestBlock()

2017-08-12 12:19:10 init message: Verifying blocks…
2017-08-12 12:19:10 pindex->GetBlockHash()=e99f253c8e758d109b7b52b17509d34196229628ead58ac3fe4ab4d278e97acc
2017-08-12 12:19:10 view.GetBestBlock()=e99f253c8e758d109b7b52b17509d34196229628ead58ac3fe4ab4d278e97acc

main.cpp - Line 1823

      LogPrintf("pindex->GetBlockHash()=%s \n",pindex->GetBlockHash().ToString());
     LogPrintf("view.GetBestBlock()=%s \n",view.GetBestBlock().ToString());

Original code

      if (fDebug)
           LogPrintf("pindex->GetBlockHash()=%s \n",pindex->GetBlockHash().ToString());
      if (fDebug)
           LogPrintf("view.GetBestBlock()=%s \n",view.GetBestBlock().ToString());

Updated code

if (fDebug)
     LogPrintf("ConnectBlock hashPrevBlock=%s \n",hashPrevBlock.ToString());
if (fDebug)
     LogPrintf("ConnectBlock view.GetBestBlock()=%s \n",view.GetBestBlock().ToString());

Code update main.cpp Line 1957

wrapper

Re: Loaded 10230 addresses from peers.dat 43ms

init.cpp Line 1109

   if (fDebug) 
         LogPrintf("Loaded %i addresses from peers.dat  %dms\n", addrman.size(), GetTimeMillis() - nStart);

Code updated

init.cpp - Line 1121

if (fDebug)
     {
            LogPrintf("mapBlockIndex.size() = %u\n",   mapBlockIndex.size());
            LogPrintf("nBestHeight = %d\n", chainActive.Height());
     }
 #ifdef ENABLE_WALLET
     if (fDebug)
          {
          LogPrintf("setKeyPool.size() = %u\n",      pwalletMain ? pwalletMain->setKeyPool.size() : 0);
          LogPrintf("mapWallet.size() = %u\n",       pwalletMain ? pwalletMain->mapWallet.size() : 0);
          LogPrintf("mapAddressBook.size() = %u\n",  pwalletMain ? pwalletMain->mapAddressBook.size() : 0);
           }
  #endif

Updated code

wrapper

Remaining Debug messages

2017-08-12 12:51:41 Feathercoin version v0.9.6.2-ftcit-Standard (2017-07-14 17:27:25 +0200)
2017-08-12 12:51:41 Using OpenSSL version OpenSSL 1.0.2g 1 Mar 2016
2017-08-12 12:51:41 Using BerkeleyDB version Berkeley DB 5.3.28: (September 9, 2013)
2017-08-12 12:51:41 Default data directory /home/wrapper/.feathercoin
2017-08-12 12:51:41 Using data directory /home/wrapper/.feathercoin
2017-08-12 12:51:41 Using at most 125 connections (1024 file descriptors available)
2017-08-12 12:51:41 Using 8 threads for script verification
2017-08-12 12:51:41 Using wallet wallet.dat
2017-08-12 12:51:41 init message: Verifying wallet…
2017-08-12 12:51:41 init message: Loading block index…
2017-08-12 12:51:56 init message: Verifying blocks…
2017-08-12 12:51:56 No coin database inconsistencies in last 289 blocks (535 transactions)
2017-08-12 12:51:56 init message: Checking ACP …
2017-08-12 12:51:56 block index 14829ms
2017-08-12 12:51:56 init message: Loading wallet…
2017-08-12 12:51:56 nFileVersion = 90602
2017-08-12 12:51:56 Keys: 0 plaintext, 0 encrypted, 149 w/ metadata, 0 total
2017-08-12 12:51:56 wallet 220ms
2017-08-12 12:51:56 init message: Loading addresses…
2017-08-12 12:51:56 init message: Done loading
2017-08-12 12:51:56 Initialization result: 1
2017-08-12 12:51:58 connect() to 73.96.36.22:9336 failed after select(): Connection refused (111)
2017-08-12 12:52:01 ERROR: GetMyExternalIP() : connection to 91.198.22.70:80 failed
2017-08-12 12:52:02 GetMyExternalIP() returned xxx.xxx.xxx.xxx
2017-08-12 12:52:02 AddLocal(xxx.xxx.xxx.xxx:9336,4)
2017-08-12 12:52:02 ext-ip thread exit
2017-08-12 12:52:07 dnsseed thread exit
2017-08-12 12:52:24 connect() to xxx.xxx.xxx.xxx:9336 failed after select(): No route to host (113)

wrapper

init.cpp Line 638

    if (GetBoolArg("-shrinkdebugfile", !fDebug))
         ShrinkDebugFile();
     if (fDebug)
         {
           LogPrintf("\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n");
           LogPrintf("Feathercoin version %s (%s)\n", FormatFullVersion(), CLIENT_DATE);
           LogPrintf("Using OpenSSL version %s\n",  SSLeay_version(SSLEAY_VERSION));
              }
 #ifdef ENABLE_WALLET
     if (fDebug) 
         LogPrintf("Using BerkeleyDB version %s\n", DbEnv::version(0, 0, 0));
 #endif
     if (fDebug)
         {
               if (!fLogTimestamps)
                   LogPrintf("Startup time: %s\n", DateTimeStrFormat("%Y-%m-%d %H:%M:%S", GetTime()));
                 LogPrintf("Default data directory %s\n", GetDefaultDataDir().string());
                 LogPrintf("Using data directory %s\n", strDataDir);
                 LogPrintf("Using at most %i connections (%i file descriptors available)\n", nMaxConnections, nFD);
         }     
      std::ostringstream strErrors;

if (fDebug) added to a number of “normal condition” debug messages.

walletdb ~ Line 700

      if (fDebug)
     {
          LogPrintf("nFileVersion = %d\n", wss.nFileVersion);
          LogPrintf("Keys: %u plaintext, %u encrypted, %u w/ metadata, %u total\n",
               wss.nKeys, wss.nCKeys, wss.nKeyMeta, wss.nKeys + wss.nCKeys);
      }

Code added

init.cpp Line 949

     if (fDebug)
         LogPrintf(" block index %15dms\n", GetTimeMillis() - nStart);

Code added

net.cpp Line 489

/// debug print
    if (fDebug)
         LogPrint("net", "trying connection %s lastseen=%.1fhrs\n",

Code added

net.cpp Line 348

       if (fDebug)  
            LogPrintf("GetMyExternalIP() received [%s] %s\n", strLine, addr.ToString());

init.cpp Line 672

if (!fDisableWallet) {
    if (fDebug)
         LogPrintf("Using wallet %s\n", strWalletFile);
    uiInterface.InitMessage(_("Verifying wallet..."));

Code added

init.cpp Line 661

    if (nScriptCheckThreads) {
        if (fDebug)
             LogPrintf("Using %u threads for script verification\n", nScriptCheckThreads);

Code added

/src/qt/bitcoin.cpp Line 446

if (fDebug)
    LogPrintf("Shutdown result: %i\n", retval);

/src/qt/bitcoin.cpp Line 390

if (fDebug)
    LogPrintf("Initialization result: %i\n", retval);

Code added

wrapper

net.cpp Line 316

if (!ConnectSocket(addrConnect, hSocket))
    {
    if (fDebug)    
         LogPrintf("GetMyExternalIP() : connection to %s failed", addrConnect.ToString());
    return true;
    }

Debug selection code added, removed from return error.

init.cpp Line 112

if (fDebug)
   LogPrintf("Shutdown : In progress...\n");

init.cpp Line 152

if (fDebug)
    LogPrintf("Shutdown : done\n");

Code added

net.cpp Line 240

if (fDebug)
    LogPrintf("AddLocal(%s,%i)\n", addr.ToString(), nScore);

net.cpp Line 1732

            {
                if (fDebug)
                   LogPrintf("IPv4 %s: %s\n", ifa->ifa_name, addr.ToString());


            }

net.cpp Line 429

    if (fDebug)
         LogPrintf("GetMyExternalIP() returned %s\n", addrLocalHost.ToStringIP());
    AddLocal(addrLocalHost, LOCAL_HTTP);

netbase.cpp Line 366

           if (fDebug)
                LogPrintf("select() for %s failed: %s\n", addrConnect.ToString(), NetworkErrorString(WSAGetLastError()));

netbase.cpp Line 385

            if (fDebug)
                LogPrintf("connect() to %s failed after select(): %s\n", addrConnect.ToString(), NetworkErrorString(nRet));

init.cpp Line 1062

    if (fDebug)
    {
         LogPrintf("%s", strErrors.str());
         LogPrintf(" wallet      %15dms\n", GetTimeMillis() - nStart);
    }

main.cpp Line 4722

    if (fDebug)
        LogPrintf("Receive checkpoint,hashCheckpoint=%s\n.",checkpoint.hashCheckpoint.ToString().c_str());

    if (checkpoint.ProcessSyncCheckpoint(pfrom))
    {
            if fDebug)
               LogPrintf("checkpoint.ProcessSyncCheckpoint(pfrom)=true, hashCheckpoint=%s\n.",checkpoint.hashCheckpoint.ToString().c_str());

Code Added

wrapper

net.cpp - Line 1771

 if (fDebug)
    LogPrintf("StopNode()\n");

net.cpp - Line 1799

   if (fDebug)
       LogPrintf("DNS seeding disabled\n");

Util.h

Various thread start end messages

   { 
         if (fDebug)
    /        LogPrintf("%s thread start\n", name);
         func();
         if (fDebug)
              LogPrintf("%s thread exit\n", name);
     }
     catch (boost::thread_interrupted)
     {
          if (fDebug)
                LogPrintf("%s thread interrupt\n", name);

Code added

/src/qt/bitcoin.cpp

if (fDebug)
    LogPrintf("Requesting initialize\n");


if (f Debug)
   LogPrintf("Requesting shutdown\n");

if (fDebug)
   LogPrintf("Stopping thread\n");
emit stopThread();
coreThread->wait();
if (fDebug)
    LogPrintf("Stopped thread\n");

Code added

     {
         if (fDebug)
             LogPrintf("Running Shutdown in thread\n");
         threadGroup.interrupt_all();
         threadGroup.join_all();
         Shutdown();
         if (fDebug)
             LogPrintf("Shutdown finished\n");

Code added

    if (fDebug)
        LogPrintf("Running AppInit2 in thread\n");

Code added

if (fDebug)
    LogPrintf("init message: %s\n", message);

Code added

if (fDebug)
    LogPrint("qt", "GUI: %s\n", msg);

Code added

if (fDebug)
     LogPrint("qt", "GUI: %s\n", qPrintable(msg));

Code added

wrapper

Remaining Messages

2017-08-12 18:01:39 Receive checkpoint,hashCheckpoint=0000000000000000000000000000000000000000000000000000000000000000
.ERROR: CSyncCheckpoint::CheckSignature() : verify signature failed
2017-08-12 18:02:05 UPNP_DeletePortMapping() returned : 0

net.cpp

        if (fDebug)
            LogPrintf("UPNP_DeletePortMapping() returned : %d\n", r);

Code added

        if(r != UPNPCOMMAND_SUCCESS)
            if (fDebug)
                 LogPrintf("UPnP: GetExternalIPAddress() returned %d\n", r);
        else

Code added

           else
                if (fDebug)
                    LogPrintf("UPnP: GetExternalIPAddress failed.\n");

Code added

            if(r!=UPNPCOMMAND_SUCCESS)
                if (fDebug)
                    LogPrintf("AddPortMapping(%s, %s, %s) failed with code %d (%s)\n",
                    port, port, lanaddr, r, strupnperror(r));

Code added

checkpointsync.cpp

if (!key.SetPubKey(ParseHex(strMasterPubKey)))
    {
    if (fDebug)
        LogPrintf("CSyncCheckpoint::CheckSignature() : SetPubKey failed");
    return true;
    }
if (!key.Verify(Hash(vchMsg.begin(), vchMsg.end()), vchSig))
    {
    if (fDebug)
        LogPrintf("CSyncCheckpoint::CheckSignature() : verify signature failed");
    return true;
    }

Code added

Wellenreiter

I’d keep the last one, as ACP checkpoint checksignature failed is relative important

wrapper

I’ve been through and added more, if (fDebug) (as opposed to just commenting them out) .

Most of the debug messages are still there, you just have to run -debug to see them. The checkpoint “error” did not seem to be a “Fault”, just a none complaint checkpoint.

wrapper

[FAQ] What is the difference between LogPrint() and LogPrintf() in the Feathercoin/Bitcoin source code?

Under normal conditions the LogPrintf() should only be used to report an unusual error, otherwise it is used during development to confirm an action and commented out for production versions.

Writing unnecessary messages to debug slows the system and takes up disk space. Whilst the debug can be shrunk, this relies on additional parameters being passed or set up at install time.

LogPrintf() statements log the output into debug.log file. LogPrint() statements only out put to the log file if -debug is set.

wrapper

main.h

 static const unsigned int DEFAULT_MAX_ORPHAN_TRANSACTIONS = 100;
  /** Default for -maxorphanblocks, maximum number of orphan blocks kept in memory */
 -static const unsigned int DEFAULT_MAX_ORPHAN_BLOCKS = 750;

 +static const unsigned int DEFAULT_MAX_ORPHAN_BLOCKS = 7500;

  /** The maximum size of a blk?????.dat file (since 0.8) */

Increased Max orphans default to 7500.

Wellenreiter

@wrapper

too high. I’d try 1500.

There is a reason to limit the max number of orphan blocks

wrapper

@Wellenreiter said in [Dev] Feathercoin 0.9.6.2 * Maintenance fix, build & upgrade issues notes.:

@wrapper

too high. I’d try 1500.

There is a reason to limit the max number of orphan blocks

I’ve tested it at 10,000 and that is (7500) what Dogecoin raised it to. There is no point it being lower, it was set too low.

Wellenreiter

@wrapper it’s a security measure against (D)DOS attacks to the BC, so it will work even when set to 10000000, but may stall the BC, if someone injects a high number of orphans. I’m not sure how many orphans an attacker could create, but…

wrapper

From the sync tests, we know there are already > 6000 ORHAN BLOCKS chains in the Blockchain already…

wrapper

https://github.com/FeatherCoin/Feathercoin/pull/216

Debug.log io review - Resultant fixes / improvements:

A large number of debug messages were only useful in development and have been commented out.

A further large number of messages only indicate information in an error condition and have will now only write out if -debug is set.

A small number of error messages are alerted during sync, because they are on an orphan chain, that is correct (to have the error). Further errors may need investigating so they were changed to write on -debug.

Because the max ORPHAN BLOCKS in a chain exceeds the current temporary memory pool during sync, this caused stalling whilst the memory was reloaded. The memory can be increased with a switch -maxorphanblocks=10000 - This has been increased from 750 to 7500, as per Dogecoin fix, is being tested for sufficiency / memory issues.

A number of LogPrintf() messages were reviewed and considered useful error messages to write to Debug.log that may help support in unusual circumstances. These were left unchainged.

UTF-8 translations were backported from 0.11.2

The Feathercoin client is now starting and stopping without creating a debug.log. When Debug is initiated the information is more succinct and relevant. The synchronization time is very significantly improved.

wrapper

Remaining Messages no Debug:

2017-08-13 13:48:40 partner xxx.xxx.xxx.xxx:9336 using obsolete version 60002; disconnecting
2017-08-13 13:48:40 ProcessMessage(version, 102 bytes) FAILED
2017-08-13 14:00:00 ERROR: CAlert::CheckSignature() : verify signature failed
2017-08-13 14:00:51 ERROR: CheckBlockHeader() : block with timestamp before last checkpoint
2017-08-13 14:00:51 ERROR: ProcessBlock() : CheckBlock FAILED
2017-08-13 14:00:51 ERROR: CheckBlockHeader() : block with timestamp before last checkpoint
2017-08-13 14:00:51 ERROR: ProcessBlock() : CheckBlock FAILED

Large block same message then :

2017-08-13 14:08:52 socket recv error Connection reset by peer (104)

~Block 1145437

src/main.cpp - Line 2835
2017-08-13 14:00:51 ERROR: CheckBlockHeader() : block with timestamp before last checkpoint

     if (deltaTime < 0)
       {
           return state.DoS(100, error("CheckBlockHeader() : block with timestamp before last checkpoint"),
         REJECT_CHECKPOINT, "time-too-old");

These are old rejected blocks, I assume, so not required on sync.

main.cpp - Updated code

     {
         if (fDebug)
              LogPrintf("CheckBlockHeader() : block with timestamp before last checkpoint");
         return state.DoS(100, NULL,
                          REJECT_CHECKPOINT, "time-too-old");
     }

Code added

main.cpp Line 3199

if (!CheckBlock(*pblock, state, INT_MAX)) 
	  return error("ProcessBlock() : CheckBlock FAILED");

Updated to :

if (!CheckBlock(*pblock, state, INT_MAX)) 
          if (fDebug)
              LogPrintf("ProcessBlock() : CheckBlock FAILED");
	  return true ;

netbase.cpp

Update with Bitcoin bug fix to correct (104) error

https://github.com/bitcoin/bitcoin/issues/4552
https://github.com/bitcoin/bitcoin/commit/109849e204f91d8b04b0e57da87e45b461096b50

wrapper

Full sync from scratch Test, 0.9.6.2 in progress

So far : 2.5 years in 13 hours : 5 hrs P/Day. - estimate 20 hrs full sync time (~4pm).

Remaining Debug messages :

2017-08-13 18:12:10 socket recv error Connection reset by peer (104)
2017-08-13 18:25:03 socket recv error Connection timed out (110)

Recommendation :

The Debug.log testing has shown that a number of operation, which were envisioned as errors initially, have occurred in the blockchain. This has meant that certain settings, loop levels or error messages are repeated during re-syncronisation of the blockchain.

Where’as 0.11.2 version already contain some speed ups that effect Bitcoin, (secp256k1) the FTC block sync is considerably reduced, but at ~22 hrs (estimate), would still seem long.

ToDo.

Set up a script and chron job to pole feathercoin during a resync and write Blocknumber every minute. This will 1200 data points to identify any problem block chains. These may indicate further settings that can be tweaked.

 feathercoind getinfo >> StallTest.txt

Preliminary test show synchronization is running pretty consistently at :

BlocksPerHour
39750
BlocksPerMinute
662

Full sync took 29 Hours, with no special settings and 4 outputs to debug, about lost connections…

BlockSycTest

Get Block count was often delayed

BlockSycTest

Blocks per minute

BlockSycTest

Testable

-dbcache to a value around 4000

8 connections limitation

Give Higher CPU Priority to Bitcoin-Qt Process
The above approach of blockchain import should be faster than syncing the whole blockchain block by block. Give the process higher CPU priority might further help speeding up the blockchain import especially you have more CPU cycle at your disposal. If you’re using Mac OS X, and assuming the Process ID (PID) of Bitcoin-Qt is 2202, use the following command to give Bitcoin-Qt process hight CPU priority:

sudo renice -20 -p 2202

*-20 is the nice value a value between -20 and +19. The lower the nice value, the higher priority the process gets.