diff --git a/doc/release-notes.md b/doc/release-notes.md --- a/doc/release-notes.md +++ b/doc/release-notes.md @@ -9,3 +9,4 @@ transactions - Remove miner policy estimator in favor of minimum fees, also remove `fee_estimates.dat`. Old copies will be left in place. + - The log timestamp format is now ISO 8601 (e.g. "2019-01-28T15:41:17Z") \ No newline at end of file diff --git a/src/init.cpp b/src/init.cpp --- a/src/init.cpp +++ b/src/init.cpp @@ -1786,8 +1786,7 @@ } if (!logger.m_log_timestamps) { - 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()); diff --git a/src/logging.cpp b/src/logging.cpp --- a/src/logging.cpp +++ b/src/logging.cpp @@ -143,16 +143,14 @@ if (m_started_new_line) { int64_t nTimeMicros = GetTimeMicros(); - strStamped = - DateTimeStrFormat("%Y-%m-%d %H:%M:%S", nTimeMicros / 1000000); + strStamped = FormatISO8601DateTime(nTimeMicros / 1000000); if (m_log_time_micros) { strStamped += strprintf(".%06d", 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/net.cpp b/src/net.cpp --- a/src/net.cpp +++ b/src/net.cpp @@ -2951,8 +2951,7 @@ nRequestTime = 0; } LogPrint(BCLog::NET, "askfor %s %d (%s) peer=%d\n", inv.ToString(), - nRequestTime, - DateTimeStrFormat("%H:%M:%S", nRequestTime / 1000000), id); + nRequestTime, FormatISO8601DateTime(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 --- a/src/qt/paymentserver.cpp +++ b/src/qt/paymentserver.cpp @@ -841,8 +841,8 @@ 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__) diff --git a/src/test/util_tests.cpp b/src/test/util_tests.cpp --- a/src/test/util_tests.cpp +++ b/src/test/util_tests.cpp @@ -146,6 +146,9 @@ "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( @@ -153,6 +156,19 @@ "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"); +} + struct TestArgsManager : public ArgsManager { std::map &GetMapArgs() { return mapArgs; } std::map> &GetMapMultiArgs() { diff --git a/src/utiltime.h b/src/utiltime.h --- a/src/utiltime.h +++ b/src/utiltime.h @@ -28,6 +28,14 @@ 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/utiltime.cpp b/src/utiltime.cpp --- a/src/utiltime.cpp +++ b/src/utiltime.cpp @@ -69,3 +69,15 @@ 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/validation.cpp b/src/validation.cpp --- a/src/validation.cpp +++ b/src/validation.cpp @@ -1056,17 +1056,17 @@ pindexFinalized = pindexNew->pprev; } - 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())); + 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), + 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())); } static void InvalidBlockFound(CBlockIndex *pindex, @@ -2147,8 +2147,7 @@ chainActive.Height(), chainActive.Tip()->nVersion, log(chainActive.Tip()->nChainWork.getdouble()) / log(2.0), (unsigned long)chainActive.Tip()->nChainTx, - DateTimeStrFormat("%Y-%m-%d %H:%M:%S", - chainActive.Tip()->GetBlockTime()), + FormatISO8601DateTime(chainActive.Tip()->GetBlockTime()), GuessVerificationProgress(config.GetChainParams().TxData(), chainActive.Tip()), pcoinsTip->DynamicMemoryUsage() * (1.0 / (1 << 20)), @@ -4432,8 +4431,7 @@ 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(config.GetChainParams().TxData(), chainActive.Tip())); return true; @@ -5364,8 +5362,7 @@ 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)); + FormatISO8601DateTime(nTimeFirst), FormatISO8601DateTime(nTimeLast)); } CBlockFileInfo *GetBlockFileInfo(size_t n) { diff --git a/src/wallet/rpcdump.cpp b/src/wallet/rpcdump.cpp --- a/src/wallet/rpcdump.cpp +++ b/src/wallet/rpcdump.cpp @@ -29,10 +29,6 @@ #include #include -static std::string EncodeDumpTime(int64_t nTime) { - return DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", nTime); -} - static int64_t DecodeDumpTime(const std::string &str) { static const boost::posix_time::ptime epoch = boost::posix_time::from_time_t(0); @@ -787,12 +783,12 @@ // 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())); + FormatISO8601DateTime(chainActive.Tip()->GetBlockTime())); file << "\n"; // add the base58check encoded extended master if the wallet uses HD @@ -814,7 +810,7 @@ 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 = EncodeDestination(keyid); CKey key; if (pwallet->GetKey(keyid, key)) { @@ -848,7 +844,7 @@ // 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", diff --git a/test/functional/combine_logs.py b/test/functional/combine_logs.py --- a/test/functional/combine_logs.py +++ b/test/functional/combine_logs.py @@ -13,7 +13,7 @@ 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 --- a/test/functional/test_framework/test_framework.py +++ b/test/functional/test_framework/test_framework.py @@ -382,7 +382,7 @@ 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') + 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)