From a7324bd799591546c2ae069f29cb82a66d427769 Mon Sep 17 00:00:00 2001 From: practicalswift Date: Wed, 28 Feb 2018 16:46:31 +0100 Subject: [PATCH] Format timestamps using ISO 8601 formatting (e.g. "2018-02-28T12:34:56Z") * Z is the zone designator for the zero UTC offset. * T is the delimiter used to separate date and time. This makes it clear for the end-user that the date/time logged is specified in UTC and not in the local time zone. --- doc/release-notes.md | 4 ++++ src/init.cpp | 2 +- src/net.cpp | 2 +- src/qt/paymentserver.cpp | 2 +- src/test/util_tests.cpp | 17 +++++++++++++++++ src/util.cpp | 10 ++++++---- src/utiltime.cpp | 12 ++++++++++++ src/utiltime.h | 8 ++++++++ src/validation.cpp | 11 +++++------ src/wallet/rpcdump.cpp | 12 ++++-------- test/functional/combine_logs.py | 2 +- .../functional/test_framework/test_framework.py | 2 +- 12 files changed, 61 insertions(+), 23 deletions(-) diff --git a/doc/release-notes.md b/doc/release-notes.md index 8fcd2a916..d08e2518c 100644 --- a/doc/release-notes.md +++ b/doc/release-notes.md @@ -93,6 +93,10 @@ Low-level RPC changes with any `-wallet=` options, there is no change in behavior, and the name of any wallet is just its `` string. +### Logging + +- The log timestamp format is now ISO 8601 (e.g. "2018-02-28T12:34:56Z"). + Credits ======= diff --git a/src/init.cpp b/src/init.cpp index 659f97fec..bc23d0ff8 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -1224,7 +1224,7 @@ bool AppInitMain() } if (!fLogTimestamps) - LogPrintf("Startup time: %s\n", DateTimeStrFormat("%Y-%m-%d %H:%M:%S", GetTime())); + LogPrintf("Startup time: %s\n", FormatISO8601DateTime(GetTime())); LogPrintf("Default data directory %s\n", GetDefaultDataDir().string()); LogPrintf("Using data directory %s\n", GetDataDir().string()); LogPrintf("Using config file %s\n", GetConfigFile(gArgs.GetArg("-conf", BITCOIN_CONF_FILENAME)).string()); diff --git a/src/net.cpp b/src/net.cpp index 33a60ac96..53a0a9b18 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -2795,7 +2795,7 @@ void CNode::AskFor(const CInv& inv) nRequestTime = it->second; else nRequestTime = 0; - LogPrint(BCLog::NET, "askfor %s %d (%s) peer=%d\n", inv.ToString(), nRequestTime, DateTimeStrFormat("%H:%M:%S", nRequestTime/1000000), id); + LogPrint(BCLog::NET, "askfor %s %d (%s) peer=%d\n", inv.ToString(), nRequestTime, FormatISO8601Time(nRequestTime/1000000), id); // Make sure not to reuse time indexes to keep things in the same order int64_t nNow = GetTimeMicros() - 1000000; diff --git a/src/qt/paymentserver.cpp b/src/qt/paymentserver.cpp index 8ad4fa31f..4b6fdc8d5 100644 --- a/src/qt/paymentserver.cpp +++ b/src/qt/paymentserver.cpp @@ -770,7 +770,7 @@ bool PaymentServer::verifyExpired(const payments::PaymentDetails& requestDetails { bool fVerified = (requestDetails.has_expires() && (int64_t)requestDetails.expires() < GetTime()); if (fVerified) { - const QString requestExpires = QString::fromStdString(DateTimeStrFormat("%Y-%m-%d %H:%M:%S", (int64_t)requestDetails.expires())); + const QString requestExpires = QString::fromStdString(FormatISO8601DateTime((int64_t)requestDetails.expires())); qWarning() << QString("PaymentServer::%1: Payment request expired \"%2\".") .arg(__func__) .arg(requestExpires); diff --git a/src/test/util_tests.cpp b/src/test/util_tests.cpp index 58f033cd8..84b61bea8 100644 --- a/src/test/util_tests.cpp +++ b/src/test/util_tests.cpp @@ -164,10 +164,27 @@ BOOST_AUTO_TEST_CASE(util_DateTimeStrFormat) BOOST_CHECK_EQUAL(DateTimeStrFormat("%Y-%m-%d %H:%M:%S", 0), "1970-01-01 00:00:00"); BOOST_CHECK_EQUAL(DateTimeStrFormat("%Y-%m-%d %H:%M:%S", 0x7FFFFFFF), "2038-01-19 03:14:07"); BOOST_CHECK_EQUAL(DateTimeStrFormat("%Y-%m-%d %H:%M:%S", 1317425777), "2011-09-30 23:36:17"); + BOOST_CHECK_EQUAL(DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", 1317425777), "2011-09-30T23:36:17Z"); + BOOST_CHECK_EQUAL(DateTimeStrFormat("%H:%M:%SZ", 1317425777), "23:36:17Z"); BOOST_CHECK_EQUAL(DateTimeStrFormat("%Y-%m-%d %H:%M", 1317425777), "2011-09-30 23:36"); BOOST_CHECK_EQUAL(DateTimeStrFormat("%a, %d %b %Y %H:%M:%S +0000", 1317425777), "Fri, 30 Sep 2011 23:36:17 +0000"); } +BOOST_AUTO_TEST_CASE(util_FormatISO8601DateTime) +{ + BOOST_CHECK_EQUAL(FormatISO8601DateTime(1317425777), "2011-09-30T23:36:17Z"); +} + +BOOST_AUTO_TEST_CASE(util_FormatISO8601Date) +{ + BOOST_CHECK_EQUAL(FormatISO8601Date(1317425777), "2011-09-30"); +} + +BOOST_AUTO_TEST_CASE(util_FormatISO8601Time) +{ + BOOST_CHECK_EQUAL(FormatISO8601Time(1317425777), "23:36:17Z"); +} + class TestArgsManager : public ArgsManager { public: diff --git a/src/util.cpp b/src/util.cpp index 82c99a3c2..62cdce301 100644 --- a/src/util.cpp +++ b/src/util.cpp @@ -315,12 +315,14 @@ static std::string LogTimestampStr(const std::string &str, std::atomic_bool *fSt if (*fStartedNewLine) { int64_t nTimeMicros = GetTimeMicros(); - strStamped = DateTimeStrFormat("%Y-%m-%d %H:%M:%S", nTimeMicros/1000000); - if (fLogTimeMicros) - strStamped += strprintf(".%06d", nTimeMicros%1000000); + strStamped = FormatISO8601DateTime(nTimeMicros/1000000); + if (fLogTimeMicros) { + strStamped.pop_back(); + strStamped += strprintf(".%06dZ", nTimeMicros%1000000); + } int64_t mocktime = GetMockTime(); if (mocktime) { - strStamped += " (mocktime: " + DateTimeStrFormat("%Y-%m-%d %H:%M:%S", mocktime) + ")"; + strStamped += " (mocktime: " + FormatISO8601DateTime(mocktime) + ")"; } strStamped += ' ' + str; } else diff --git a/src/utiltime.cpp b/src/utiltime.cpp index e90817313..8a861039b 100644 --- a/src/utiltime.cpp +++ b/src/utiltime.cpp @@ -85,3 +85,15 @@ std::string DateTimeStrFormat(const char* pszFormat, int64_t nTime) ss << boost::posix_time::from_time_t(nTime); return ss.str(); } + +std::string FormatISO8601DateTime(int64_t nTime) { + return DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", nTime); +} + +std::string FormatISO8601Date(int64_t nTime) { + return DateTimeStrFormat("%Y-%m-%d", nTime); +} + +std::string FormatISO8601Time(int64_t nTime) { + return DateTimeStrFormat("%H:%M:%SZ", nTime); +} diff --git a/src/utiltime.h b/src/utiltime.h index 56cc31da6..807c52ffa 100644 --- a/src/utiltime.h +++ b/src/utiltime.h @@ -27,6 +27,14 @@ void SetMockTime(int64_t nMockTimeIn); int64_t GetMockTime(); void MilliSleep(int64_t n); +/** + * ISO 8601 formatting is preferred. Use the FormatISO8601{DateTime,Date,Time} + * helper functions if possible. + */ std::string DateTimeStrFormat(const char* pszFormat, int64_t nTime); +std::string FormatISO8601DateTime(int64_t nTime); +std::string FormatISO8601Date(int64_t nTime); +std::string FormatISO8601Time(int64_t nTime); + #endif // BITCOIN_UTILTIME_H diff --git a/src/validation.cpp b/src/validation.cpp index 51e40c17b..c677f44b3 100644 --- a/src/validation.cpp +++ b/src/validation.cpp @@ -1267,13 +1267,12 @@ void static InvalidChainFound(CBlockIndex* pindexNew) LogPrintf("%s: invalid block=%s height=%d log2_work=%.8g date=%s\n", __func__, pindexNew->GetBlockHash().ToString(), pindexNew->nHeight, - log(pindexNew->nChainWork.getdouble())/log(2.0), DateTimeStrFormat("%Y-%m-%d %H:%M:%S", - pindexNew->GetBlockTime())); + log(pindexNew->nChainWork.getdouble())/log(2.0), FormatISO8601DateTime(pindexNew->GetBlockTime())); CBlockIndex *tip = chainActive.Tip(); assert (tip); LogPrintf("%s: current best=%s height=%d log2_work=%.8g date=%s\n", __func__, tip->GetBlockHash().ToString(), chainActive.Height(), log(tip->nChainWork.getdouble())/log(2.0), - DateTimeStrFormat("%Y-%m-%d %H:%M:%S", tip->GetBlockTime())); + FormatISO8601DateTime(tip->GetBlockTime())); CheckForkWarningConditions(); } @@ -2229,7 +2228,7 @@ void static UpdateTip(const CBlockIndex *pindexNew, const CChainParams& chainPar LogPrintf("%s: new best=%s height=%d version=0x%08x log2_work=%.8g tx=%lu date='%s' progress=%f cache=%.1fMiB(%utxo)", __func__, pindexNew->GetBlockHash().ToString(), pindexNew->nHeight, pindexNew->nVersion, log(pindexNew->nChainWork.getdouble())/log(2.0), (unsigned long)pindexNew->nChainTx, - DateTimeStrFormat("%Y-%m-%d %H:%M:%S", pindexNew->GetBlockTime()), + FormatISO8601DateTime(pindexNew->GetBlockTime()), GuessVerificationProgress(chainParams.TxData(), pindexNew), pcoinsTip->DynamicMemoryUsage() * (1.0 / (1<<20)), pcoinsTip->GetCacheSize()); if (!warningMessages.empty()) LogPrintf(" warning='%s'", boost::algorithm::join(warningMessages, ", ")); @@ -3856,7 +3855,7 @@ bool LoadChainTip(const CChainParams& chainparams) LogPrintf("Loaded best chain: hashBestChain=%s height=%d date=%s progress=%f\n", chainActive.Tip()->GetBlockHash().ToString(), chainActive.Height(), - DateTimeStrFormat("%Y-%m-%d %H:%M:%S", chainActive.Tip()->GetBlockTime()), + FormatISO8601DateTime(chainActive.Tip()->GetBlockTime()), GuessVerificationProgress(chainparams.TxData(), chainActive.Tip())); return true; } @@ -4554,7 +4553,7 @@ void CChainState::CheckBlockIndex(const Consensus::Params& consensusParams) std::string CBlockFileInfo::ToString() const { - return strprintf("CBlockFileInfo(blocks=%u, size=%u, heights=%u...%u, time=%s...%s)", nBlocks, nSize, nHeightFirst, nHeightLast, DateTimeStrFormat("%Y-%m-%d", nTimeFirst), DateTimeStrFormat("%Y-%m-%d", nTimeLast)); + return strprintf("CBlockFileInfo(blocks=%u, size=%u, heights=%u...%u, time=%s...%s)", nBlocks, nSize, nHeightFirst, nHeightLast, FormatISO8601Date(nTimeFirst), FormatISO8601Date(nTimeLast)); } CBlockFileInfo* GetBlockFileInfo(size_t n) diff --git a/src/wallet/rpcdump.cpp b/src/wallet/rpcdump.cpp index 0edc8d8d6..c7c54ecb9 100644 --- a/src/wallet/rpcdump.cpp +++ b/src/wallet/rpcdump.cpp @@ -28,10 +28,6 @@ #include -std::string static EncodeDumpTime(int64_t nTime) { - return DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", nTime); -} - int64_t static DecodeDumpTime(const std::string &str) { static const boost::posix_time::ptime epoch = boost::posix_time::from_time_t(0); static const std::locale loc(std::locale::classic(), @@ -722,9 +718,9 @@ UniValue dumpwallet(const JSONRPCRequest& request) // produce output file << strprintf("# Wallet dump created by Bitcoin %s\n", CLIENT_BUILD); - file << strprintf("# * Created on %s\n", EncodeDumpTime(GetTime())); + file << strprintf("# * Created on %s\n", FormatISO8601DateTime(GetTime())); file << strprintf("# * Best block at time of backup was %i (%s),\n", chainActive.Height(), chainActive.Tip()->GetBlockHash().ToString()); - file << strprintf("# mined on %s\n", EncodeDumpTime(chainActive.Tip()->GetBlockTime())); + file << strprintf("# mined on %s\n", FormatISO8601DateTime(chainActive.Tip()->GetBlockTime())); file << "\n"; // add the base58check encoded extended master if the wallet uses HD @@ -741,7 +737,7 @@ UniValue dumpwallet(const JSONRPCRequest& request) } for (std::vector >::const_iterator it = vKeyBirth.begin(); it != vKeyBirth.end(); it++) { const CKeyID &keyid = it->second; - std::string strTime = EncodeDumpTime(it->first); + std::string strTime = FormatISO8601DateTime(it->first); std::string strAddr; std::string strLabel; CKey key; @@ -769,7 +765,7 @@ UniValue dumpwallet(const JSONRPCRequest& request) // get birth times for scripts with metadata auto it = pwallet->m_script_metadata.find(scriptid); if (it != pwallet->m_script_metadata.end()) { - create_time = EncodeDumpTime(it->second.nCreateTime); + create_time = FormatISO8601DateTime(it->second.nCreateTime); } if(pwallet->GetCScript(scriptid, script)) { file << strprintf("%s %s script=1", HexStr(script.begin(), script.end()), create_time); diff --git a/test/functional/combine_logs.py b/test/functional/combine_logs.py index 3ca74ea35..d1bf9206b 100755 --- a/test/functional/combine_logs.py +++ b/test/functional/combine_logs.py @@ -13,7 +13,7 @@ import re import sys # Matches on the date format at the start of the log event -TIMESTAMP_PATTERN = re.compile(r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{6}") +TIMESTAMP_PATTERN = re.compile(r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}Z") LogEvent = namedtuple('LogEvent', ['timestamp', 'source', 'event']) diff --git a/test/functional/test_framework/test_framework.py b/test/functional/test_framework/test_framework.py index 86c1150ab..f4e77d32d 100755 --- a/test/functional/test_framework/test_framework.py +++ b/test/functional/test_framework/test_framework.py @@ -358,7 +358,7 @@ class BitcoinTestFramework(): ll = int(self.options.loglevel) if self.options.loglevel.isdigit() else self.options.loglevel.upper() ch.setLevel(ll) # Format logs the same as bitcoind's debug.log with microprecision (so log files can be concatenated and sorted) - formatter = logging.Formatter(fmt='%(asctime)s.%(msecs)03d000 %(name)s (%(levelname)s): %(message)s', datefmt='%Y-%m-%d %H:%M:%S') + formatter = logging.Formatter(fmt='%(asctime)s.%(msecs)03d000Z %(name)s (%(levelname)s): %(message)s', datefmt='%Y-%m-%dT%H:%M:%S') formatter.converter = time.gmtime fh.setFormatter(formatter) ch.setFormatter(formatter)