Default log timestamps are now human-friendly, plus nits and fixups. (#…

…25)

- Log timestamps now default to localtime [yyy-mm-dd hh:mm:ss.zzz]. The
old behavior (abs time since program start) can be enabled using the new
--ts-format uptime CLI (and conf) argument.

- Log timestamps now default to "none" (no timestamp) if running in syslog
mode (-S).

- Added --ts-format and ts-format= CLI/conf arg for controlling the log
timestamp format.  Log timestamps can be suppressed altogether with
--ts-foramt none

- Bumped version to v1.1.1

- Updated documentation: man page as well as sample conf to describe
this new --ts-format/ts-format= CLI/conf variable.

- Made Debug() and Trace() logging more efficient by not evaluating the
arguments in the common !Debug::isEnabled() or !Trace::isEnabled() case.
We had to resort to using a C-style macro to accomplish this.

- Replaced most uses of `__FUNCTION__` in the codebase with the more
C++-ey `__func__`.

- Various other small nits and fixups.  Overall the app should eat
slightly fewer cycles since all the verbose logging are now no-ops in
the common case (before we were building strings only to throw them away
later).

contrib/rpm/fulcrum.spec

@@ -1,5 +1,5 @@
 Name:    {{{ git_name name="fulcrum" }}}
-Version: 1.1.0
+Version: 1.1.1
 Release: {{{ git_version }}}%{?dist}
 Summary: A fast & nimble SPV server for Bitcoin Cash
 

doc/fulcrum-example-config.conf

@@ -706,6 +706,15 @@ rpcpassword = hunter1
 #subnets_to_exclude_from_per_ip_limits = 127.0.0.1/32, ::1/128
 
 
+# Log timestamp format - 'ts-format' - DEFAULT: localtime
+#
+# Specify the log timestamp format, one of: none, uptime, localtime, utc. If
+# unspecified, the default is "localtime". Before this option was introduced,
+# previous versions of Fulcrum always logged using "uptime".
+#
+#ts-format = localtime
+#
+
 # Work queue size - 'workqueue' - DEFAULT: 10000
 #
 # The maximum size of the work queue. Requests from clients that require further

doc/unix-man-page.md

@@ -1,6 +1,6 @@
-% FULCRUM(1) Version 1.1.0 | Fulcrum Manual
+% FULCRUM(1) Version 1.1.1 | Fulcrum Manual
 % Fulcrum is written by Calin Culianu (cculianu)
-% April 15, 2020
+% May 13, 2020
 
 # NAME
 
@@ -96,6 +96,9 @@ Once the server finishes synching it will behave like an ElectronX/ElectrumX ser
 -T, --polltime <polltime>
 :   The number of seconds for the bitcoind poll interval. Bitcoind is polled once every `polltime` seconds to detect mempool and blockchain changes. This value must be at least 0.5 and cannot exceed 30. If not specified, defaults to 2 seconds.
 
+--ts-format <keyword>
+:   Specify log timestamp format, one of: "none", "uptime", "localtime", or "utc". If unspecified, default is "localtime" (previous versions of Fulcrum always logged using "uptime").
+
 --dump-sh <outputfile>
 :    *This is an advanced debugging option*. Dump script hashes. If specified, after the database is loaded, all of the script hashes in the database will be written to outputfile as a JSON array.
 

src/AbstractConnection.cpp

@@ -119,8 +119,7 @@ void AbstractConnection::setMaxBuffer(qint64 maxBytes)
     MAX_BUFFER = Options::clampMaxBufferSetting(int(maxBytes));
     if (socket && thread() == QThread::currentThread()) {
         socket->setReadBufferSize(MAX_BUFFER);
-        if (Debug::isEnabled())
-            Debug() << prettyName() << " set max_buffer to " << MAX_BUFFER << ", socket says: " << socket->readBufferSize();
+        DebugM(prettyName(), " set max_buffer to ", MAX_BUFFER, ", socket says: ", socket->readBufferSize());
     }
 }
 
@@ -129,11 +128,11 @@ void AbstractConnection::do_disconnect(bool graceful)
     status = status == Bad ? Bad : NotConnected;  // try and keep Bad status around so PeerMgr can decide when to reconnect based on it? TODO: remove this concept from the codebase
     if (socket) {
         if (!graceful) {
-            Debug() << __func__ << " (abort) " << id;
+            DebugM(__func__, " (abort) ", id);
             socket->abort();  // this will set status too because state change, but we set it first above to be paranoid
         } else {
             socket->disconnectFromHost();
-            Debug() << __func__ << " (graceful) " << id;
+            DebugM(__func__, " (graceful) ", id);
         }
     }
 }
@@ -168,11 +167,11 @@ bool AbstractConnection::do_write(const QByteArray & data)
         err = " called from another thread! FIXME!";
     }
     if (!err.isEmpty()) {
-        Error() << __FUNCTION__ << " (" << objectName() << ") " << err << " id=" << id;
+        Error() << __func__ << " (" << objectName() << ") " << err << " id=" << id;
         return false;
     }
     if (writeBackLog > MAX_BUFFER) {
-        Warning(Log::Magenta) << __FUNCTION__ << ": " << prettyName() << " -- MAX_BUFFER reached on write (" << MAX_BUFFER << "), disconnecting client";
+        Warning(Log::Magenta) << __func__ << ": " << prettyName() << " -- MAX_BUFFER reached on write (" << MAX_BUFFER << "), disconnecting client";
         do_disconnect();
         return false;
     }
@@ -183,7 +182,7 @@ bool AbstractConnection::do_write(const QByteArray & data)
     writeBackLog += n2write;
     const qint64 written = socket->write(data);
     if (UNLIKELY(written < 0)) {
-        Error() << __FUNCTION__ << ": " << prettyName() << " -- error on write " << socket->error() << " (" << socket->errorString() << ")";
+        Error() << __func__ << ": " << prettyName() << " -- error on write " << socket->error() << " (" << socket->errorString() << ")";
         do_disconnect();
         return false;
     } else if (UNLIKELY(written < n2write)) {
@@ -192,7 +191,7 @@ bool AbstractConnection::do_write(const QByteArray & data)
         // however, in case some day this predicate is violated by a Qt API change.
         //
         // See: https://code.woboq.org/qt5/qtbase/src/network/socket/qabstractsocket.cpp.html#_ZN15QAbstractSocket9writeDataEPKcx
-        Error() << __FUNCTION__ << ": " << prettyName() << " -- short write count; expected to write " << n2write
+        Error() << __func__ << ": " << prettyName() << " -- short write count; expected to write " << n2write
                 << " bytes, but wrote " << written << " bytes instead. This should never happen! FIXME!";
         return false;
     }
@@ -205,7 +204,7 @@ void AbstractConnection::slot_on_readyRead() { on_readyRead(); }
 void AbstractConnection::on_connected()
 {
     // runs in our thread's context
-    Debug() << __func__ << " " << id;
+    DebugM(__func__, " ", id);
     connectedTS = Util::getTime();
     setSockOpts(socket); // ensure nagling disabled
     socket->setReadBufferSize(MAX_BUFFER); // ensure memory exhaustion from peer can't happen in case we're too busy to read.
@@ -214,7 +213,7 @@ void AbstractConnection::on_connected()
     connectedConns.push_back(connect(socket, SIGNAL(bytesWritten(qint64)), this, SLOT(on_bytesWritten(qint64))));
     connectedConns.push_back(
         connect(socket, &QAbstractSocket::disconnected, this, [this]{
-            Debug() << prettyName() << " socket disconnected";
+            DebugM(prettyName(), " socket disconnected");
             for (const auto & connection : connectedConns) {
                 QObject::disconnect(connection);
             }
@@ -243,7 +242,7 @@ void AbstractConnection::on_disconnected()
 
 void AbstractConnection::on_socketState(QAbstractSocket::SocketState s)
 {
-    Debug() << prettyName() << " socket state: " << s;
+    DebugM(prettyName(), " socket state: ",  int(s));
     switch (s) {
     case QAbstractSocket::ConnectedState:
         status = Connected;
@@ -262,16 +261,16 @@ void AbstractConnection::on_socketState(QAbstractSocket::SocketState s)
 
 void AbstractConnection::on_bytesWritten(qint64 nBytes)
 {
-    Trace() << __FUNCTION__;
+    TraceM(__func__);
     writeBackLog -= nBytes;
     if (writeBackLog > 0 && status == Connected && socket) {
-        Debug() << prettyName() << " writeBackLog size: " << writeBackLog << " (wrote just now: " << nBytes << ")";
+        DebugM(prettyName(), " writeBackLog size: ", writeBackLog, " (wrote just now: ", nBytes, ")");
     }
 }
 
 void AbstractConnection::do_ping()
 {
-    Debug() << __FUNCTION__ << " " << prettyName() << " stub ...";
+    DebugM(__func__, " ", prettyName(), " stub ...");
 }
 
 void AbstractConnection::on_error(QAbstractSocket::SocketError err)

src/App.cpp

@@ -227,7 +227,7 @@ void App::parseArgs()
         { { "a", "admin" },
           QString("Specify a <port> or an <interface:port> on which to listen for TCP connections for the admin RPC service."
                   " The admin service is used for sending special control commands to the server, such as stopping"
-                  " the server, and it should *NOT* be exposed to the internet.  This option is required if you wish to"
+                  " the server, and it should *NOT* be exposed to the internet. This option is required if you wish to"
                   " use the FulcrumAdmin CLI tool to send commands to Fulcrum. It is recommended that you specify the"
                   " loopback address as the bind interface for this option such as: <port> by itself or 127.0.0.1:<port> for"
                   " IPv4 and/or ::1:<port> for IPv6. If no interface is specified, and just a port number by itself is"
@@ -237,7 +237,7 @@ void App::parseArgs()
          },
          { { "z", "stats" },
            QString("Specify listen address and port for the stats HTTP server. Format is same as the -s, -t or -a options,"
-           " e.g.: <interface:port>. Default is to not start any starts HTTP servers.  Also, like the -a option, you may"
+           " e.g.: <interface:port>. Default is to not start any starts HTTP servers. Also, like the -a option, you may"
            " specify a port number by itself here and 127.0.0.1:<port> will be assumed."
            " This option may be specified more than once to bind to multiple interfaces and/or ports."),
            QString("[interface:]port"),
@@ -250,14 +250,14 @@ void App::parseArgs()
          },
          { { "u", "rpcuser" },
            QString("Specify a username to use for authenticating to bitcoind. This is a required option, along"
-           " with -b and -p.  This option should be the same username you specified in your bitcoind.conf file"
+           " with -b and -p. This option should be the same username you specified in your bitcoind.conf file"
            " under rpcuser=. For security, you may omit this option from the command-line and use the %1"
            " environment variable instead (the CLI arg takes precedence if both are present).").arg(RPCUSER),
            QString("username"),
          },
          { { "p", "rpcpassword" },
            QString("Specify a password to use for authenticating to bitcoind. This is a required option, along"
-           " with -b and -u.  This option should be the same password you specified in your bitcoind.conf file"
+           " with -b and -u. This option should be the same password you specified in your bitcoind.conf file"
            " under rpcpassword=. For security, you may omit this option from the command-line and use the"
            " %1 environment variable instead (the CLI arg takes precedence if both are present).").arg(RPCPASSWORD),
            QString("password"),
@@ -270,7 +270,8 @@ void App::parseArgs()
            QString("Suppress debug output. This is the default on release builds. This is the opposite of -d."),
          },
          { { "S", "syslog" },
-           QString("Syslog mode. If on Unix, use the syslog() facility to produce log messages. This option currently has no effect on Windows."),
+           QString("Syslog mode. If on Unix, use the syslog() facility to produce log messages."
+                   " This option currently has no effect on Windows."),
          },
          { { "C", "checkdb" },
            QString("If specified, database consistency will be checked thoroughly for sanity & integrity."
@@ -282,6 +283,13 @@ void App::parseArgs()
                    " 30. If not specified, defaults to %1 seconds.").arg(Options::defaultPollTimeSecs),
            QString("polltime"), QString::number(Options::defaultPollTimeSecs)
          },
+         {
+           "ts-format",
+           QString("Specify log timestamp format, one of: \"none\", \"uptime\", \"localtime\", or \"utc\". "
+                   "If unspecified, default is \"localtime\" (previous versions of " APPNAME " always logged using "
+                   "\"uptime\")."),
+           QString("keyword"),
+         },
          {
            "dump-sh",
            QString("*** This is an advanced debugging option ***   Dump script hashes. If specified, after the database"
@@ -300,7 +308,7 @@ void App::parseArgs()
     // but CLI args take precedence over config file options.
     if (auto posArgs = parser.positionalArguments(); !posArgs.isEmpty()) {
         if (posArgs.size() > 1)
-            throw BadArgs("More than 1 config file was specified.  Please specify at most 1 config file.");
+            throw BadArgs("More than 1 config file was specified. Please specify at most 1 config file.");
         const auto file = posArgs.first();
         if (!conf.open(file))
             throw BadArgs(QString("Unable to open config file %1").arg(file));
@@ -831,6 +839,29 @@ void App::parseArgs()
         });
     }
 
+    // parse --ts-format or ts-format= from conf (ts_format also supported from conf)
+    if (auto fmt = parser.value("ts-format");
+            !fmt.isEmpty() || !(fmt = conf.value("ts-format")).isEmpty() || !(fmt = conf.value("ts_format")).isEmpty()) {
+        fmt = fmt.toLower().trimmed();
+        if (fmt == "uptime" || fmt == "abs" || fmt == "abstime")
+            options->logTimestampMode = Options::LogTimestampMode::Uptime;
+        else if (fmt.startsWith("local"))
+            options->logTimestampMode = Options::LogTimestampMode::Local;
+        else if (fmt == "utc")
+            options->logTimestampMode = Options::LogTimestampMode::UTC;
+        else if (fmt == "none")
+            options->logTimestampMode = Options::LogTimestampMode::None;
+        else
+            throw BadArgs(QString("ts-format: unrecognized value \"%1\"").arg(fmt));
+        Util::AsyncOnObject(this, [this]{ DebugM("config: ts-format = ", options->logTimestampModeString()); });
+    }
+#ifdef Q_OS_UNIX
+    else if (options->syslogMode) {
+        options->logTimestampMode = Options::LogTimestampMode::None;
+        Util::AsyncOnObject(this, []{ DebugM("syslog mode enabled, defaulting to \"--ts-format none\""); });
+    }
+#endif
+
     // parse --dump-*
     if (const auto outFile = parser.value("dump-sh"); !outFile.isEmpty()) {
         options->dumpScriptHashes = outFile; // we do no checking here, but Controller::startup will throw BadArgs if it cannot open this file for writing.

src/BTC_Address.cpp

@@ -118,7 +118,7 @@ namespace BTC
             if (dec.size() != 21) {
                 // this should never happen
 #ifdef QT_DEBUG
-                Debug() << __FUNCTION__ << ": bad decoded length  " << dec.size() << " for address " << legacyOrCash;
+                DebugM(__func__, ": bad decoded length  ", dec.size(), " for address ", legacyOrCash);
 #endif
             } else {
                 a.verByte = dec[0];
@@ -133,7 +133,7 @@ namespace BTC
             try {
                 if (!(ok = DecodeCash(a, ss))) {
 #ifdef QT_DEBUG
-                    Debug() << __FUNCTION__ << ": got bad address " << legacyOrCash;
+                    DebugM(__func__, ": got bad address ", legacyOrCash);
 #endif
                 }
             } catch (const std::exception &e) {

src/BitcoinD.cpp

@@ -47,7 +47,7 @@ void BitcoinDMgr::startup() {
         connect(client.get(), &BitcoinD::authenticated, this, [this](BitcoinD *b){
             // guard against stale/old signal
             if (!b->isGood()) {
-                Debug() << "got authenticated for id:" << b->id << " but isGood() is false!";
+                DebugM("got authenticated for id:", b->id, " but isGood() is false!");
                 return; // false/stale signal
             }
             const bool wasEmpty = goodSet.empty();
@@ -58,7 +58,7 @@ void BitcoinDMgr::startup() {
         connect(client.get(), &BitcoinD::lostConnection, this, [this](AbstractConnection *c){
             // guard against stale/old signal
             if (c->isGood()) {
-                Debug() << "got lostConnection for id:" << c->id << " but isGood() is true!";
+                DebugM("got lostConnection for id:", c->id, " but isGood() is true!");
                 return; // false/stale signal
             }
             goodSet.erase(c->id);
@@ -96,11 +96,11 @@ void BitcoinDMgr::cleanup() {
 
 void BitcoinDMgr::on_Message(quint64 bid, const RPC::Message &msg)
 {
-    if (Trace::isEnabled()) Trace() << "Msg from: " << bid << " method=" << msg.method;
+    TraceM("Msg from: ", bid, " method=", msg.method);
 }
 void BitcoinDMgr::on_ErrorMessage(quint64 bid, const RPC::Message &msg)
 {
-    Debug() << "ErrMsg from: " << bid << " (reqId: " << msg.id.toString() << ") error=" << msg.errorMessage();
+    DebugM("ErrMsg from: ", bid, " (reqId: ", msg.id.toString(),") error=", msg.errorMessage());
     if (msg.errorCode() == bitcoin::RPCErrorCode::RPC_IN_WARMUP) {
         emit inWarmUp(msg.errorMessage());
     }
@@ -157,8 +157,8 @@ void BitcoinDMgr::submitRequest(QObject *sender, const RPC::Message::Id &rid, co
     // to happen either as a result of a successful request reply, or due to bitcoind failure.
     auto context = std::shared_ptr<ReqCtxObj>(new ReqCtxObj, [](ReqCtxObj *context){
         if constexpr (debugDeletes) {
-            Debug() << context->objectName() << " shptr deleter";
-            connect(context, &QObject::destroyed, qApp, [n=context->objectName()]{ Debug() << n << " destroyed"; }, Qt::DirectConnection);
+            DebugM(context->objectName(), " shptr deleter");
+            connect(context, &QObject::destroyed, qApp, [n=context->objectName()]{ DebugM(n, " destroyed"); }, Qt::DirectConnection);
         }
         context->deleteLater();
     });
@@ -288,7 +288,7 @@ void BitcoinD::on_started()
         const auto SetTimer = [this] {
             callOnTimerSoon(5000, reconnectTimer, [this]{
                 if (!isGood()) {
-                    Debug() << prettyName() << " reconnecting...";
+                    DebugM(prettyName(), " reconnecting...");
                     reconnect();
                     return true; // keep the timer alive
                 }
@@ -337,7 +337,7 @@ void BitcoinD::on_connected()
 void BitcoinD::do_ping()
 {
     if (isStale()) {
-        Debug() << "Stale connection, reconnecting.";
+        DebugM("Stale connection, reconnecting.");
         reconnect();
     } else
         emit sendRequest(newId(), "ping");

src/Common.h

@@ -38,7 +38,7 @@ struct InternalError : public Exception { using Exception::Exception; };
 struct BadArgs : public Exception { using Exception::Exception; };
 
 #define APPNAME "Fulcrum"
-#define VERSION "1.1.0"
+#define VERSION "1.1.1"
 #ifdef QT_DEBUG
 #  define VERSION_EXTRA "(Debug)"
 inline constexpr bool isReleaseBuild() { return false; }