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.
This commit is contained in:
practicalswift 2018-02-28 16:46:31 +01:00
parent 29fad97c32
commit a7324bd799
12 changed files with 61 additions and 23 deletions

View file

@ -93,6 +93,10 @@ Low-level RPC changes
with any `-wallet=<path>` options, there is no change in behavior, and the with any `-wallet=<path>` options, there is no change in behavior, and the
name of any wallet is just its `<path>` string. name of any wallet is just its `<path>` string.
### Logging
- The log timestamp format is now ISO 8601 (e.g. "2018-02-28T12:34:56Z").
Credits Credits
======= =======

View file

@ -1224,7 +1224,7 @@ bool AppInitMain()
} }
if (!fLogTimestamps) 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("Default data directory %s\n", GetDefaultDataDir().string());
LogPrintf("Using data directory %s\n", GetDataDir().string()); LogPrintf("Using data directory %s\n", GetDataDir().string());
LogPrintf("Using config file %s\n", GetConfigFile(gArgs.GetArg("-conf", BITCOIN_CONF_FILENAME)).string()); LogPrintf("Using config file %s\n", GetConfigFile(gArgs.GetArg("-conf", BITCOIN_CONF_FILENAME)).string());

View file

@ -2795,7 +2795,7 @@ void CNode::AskFor(const CInv& inv)
nRequestTime = it->second; nRequestTime = it->second;
else else
nRequestTime = 0; 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 // Make sure not to reuse time indexes to keep things in the same order
int64_t nNow = GetTimeMicros() - 1000000; int64_t nNow = GetTimeMicros() - 1000000;

View file

@ -770,7 +770,7 @@ bool PaymentServer::verifyExpired(const payments::PaymentDetails& requestDetails
{ {
bool fVerified = (requestDetails.has_expires() && (int64_t)requestDetails.expires() < GetTime()); bool fVerified = (requestDetails.has_expires() && (int64_t)requestDetails.expires() < GetTime());
if (fVerified) { 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\".") qWarning() << QString("PaymentServer::%1: Payment request expired \"%2\".")
.arg(__func__) .arg(__func__)
.arg(requestExpires); .arg(requestExpires);

View file

@ -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", 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", 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-%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("%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_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 class TestArgsManager : public ArgsManager
{ {
public: public:

View file

@ -315,12 +315,14 @@ static std::string LogTimestampStr(const std::string &str, std::atomic_bool *fSt
if (*fStartedNewLine) { if (*fStartedNewLine) {
int64_t nTimeMicros = GetTimeMicros(); int64_t nTimeMicros = GetTimeMicros();
strStamped = DateTimeStrFormat("%Y-%m-%d %H:%M:%S", nTimeMicros/1000000); strStamped = FormatISO8601DateTime(nTimeMicros/1000000);
if (fLogTimeMicros) if (fLogTimeMicros) {
strStamped += strprintf(".%06d", nTimeMicros%1000000); strStamped.pop_back();
strStamped += strprintf(".%06dZ", nTimeMicros%1000000);
}
int64_t mocktime = GetMockTime(); int64_t mocktime = GetMockTime();
if (mocktime) { if (mocktime) {
strStamped += " (mocktime: " + DateTimeStrFormat("%Y-%m-%d %H:%M:%S", mocktime) + ")"; strStamped += " (mocktime: " + FormatISO8601DateTime(mocktime) + ")";
} }
strStamped += ' ' + str; strStamped += ' ' + str;
} else } else

View file

@ -85,3 +85,15 @@ std::string DateTimeStrFormat(const char* pszFormat, int64_t nTime)
ss << boost::posix_time::from_time_t(nTime); ss << boost::posix_time::from_time_t(nTime);
return ss.str(); 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);
}

View file

@ -27,6 +27,14 @@ void SetMockTime(int64_t nMockTimeIn);
int64_t GetMockTime(); int64_t GetMockTime();
void MilliSleep(int64_t n); 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 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 #endif // BITCOIN_UTILTIME_H

View file

@ -1267,13 +1267,12 @@ void static InvalidChainFound(CBlockIndex* pindexNew)
LogPrintf("%s: invalid block=%s height=%d log2_work=%.8g date=%s\n", __func__, LogPrintf("%s: invalid block=%s height=%d log2_work=%.8g date=%s\n", __func__,
pindexNew->GetBlockHash().ToString(), pindexNew->nHeight, pindexNew->GetBlockHash().ToString(), pindexNew->nHeight,
log(pindexNew->nChainWork.getdouble())/log(2.0), DateTimeStrFormat("%Y-%m-%d %H:%M:%S", log(pindexNew->nChainWork.getdouble())/log(2.0), FormatISO8601DateTime(pindexNew->GetBlockTime()));
pindexNew->GetBlockTime()));
CBlockIndex *tip = chainActive.Tip(); CBlockIndex *tip = chainActive.Tip();
assert (tip); assert (tip);
LogPrintf("%s: current best=%s height=%d log2_work=%.8g date=%s\n", __func__, 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), 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(); 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__, 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, pindexNew->GetBlockHash().ToString(), pindexNew->nHeight, pindexNew->nVersion,
log(pindexNew->nChainWork.getdouble())/log(2.0), (unsigned long)pindexNew->nChainTx, 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()); GuessVerificationProgress(chainParams.TxData(), pindexNew), pcoinsTip->DynamicMemoryUsage() * (1.0 / (1<<20)), pcoinsTip->GetCacheSize());
if (!warningMessages.empty()) if (!warningMessages.empty())
LogPrintf(" warning='%s'", boost::algorithm::join(warningMessages, ", ")); 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", LogPrintf("Loaded best chain: hashBestChain=%s height=%d date=%s progress=%f\n",
chainActive.Tip()->GetBlockHash().ToString(), chainActive.Height(), 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())); GuessVerificationProgress(chainparams.TxData(), chainActive.Tip()));
return true; return true;
} }
@ -4554,7 +4553,7 @@ void CChainState::CheckBlockIndex(const Consensus::Params& consensusParams)
std::string CBlockFileInfo::ToString() const 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) CBlockFileInfo* GetBlockFileInfo(size_t n)

View file

@ -28,10 +28,6 @@
#include <univalue.h> #include <univalue.h>
std::string static EncodeDumpTime(int64_t nTime) {
return DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", nTime);
}
int64_t static DecodeDumpTime(const std::string &str) { int64_t static DecodeDumpTime(const std::string &str) {
static const boost::posix_time::ptime epoch = boost::posix_time::from_time_t(0); static const boost::posix_time::ptime epoch = boost::posix_time::from_time_t(0);
static const std::locale loc(std::locale::classic(), static const std::locale loc(std::locale::classic(),
@ -722,9 +718,9 @@ UniValue dumpwallet(const JSONRPCRequest& request)
// produce output // produce output
file << strprintf("# Wallet dump created by Bitcoin %s\n", CLIENT_BUILD); 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("# * 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"; file << "\n";
// add the base58check encoded extended master if the wallet uses HD // add the base58check encoded extended master if the wallet uses HD
@ -741,7 +737,7 @@ UniValue dumpwallet(const JSONRPCRequest& request)
} }
for (std::vector<std::pair<int64_t, CKeyID> >::const_iterator it = vKeyBirth.begin(); it != vKeyBirth.end(); it++) { for (std::vector<std::pair<int64_t, CKeyID> >::const_iterator it = vKeyBirth.begin(); it != vKeyBirth.end(); it++) {
const CKeyID &keyid = it->second; const CKeyID &keyid = it->second;
std::string strTime = EncodeDumpTime(it->first); std::string strTime = FormatISO8601DateTime(it->first);
std::string strAddr; std::string strAddr;
std::string strLabel; std::string strLabel;
CKey key; CKey key;
@ -769,7 +765,7 @@ UniValue dumpwallet(const JSONRPCRequest& request)
// get birth times for scripts with metadata // get birth times for scripts with metadata
auto it = pwallet->m_script_metadata.find(scriptid); auto it = pwallet->m_script_metadata.find(scriptid);
if (it != pwallet->m_script_metadata.end()) { if (it != pwallet->m_script_metadata.end()) {
create_time = EncodeDumpTime(it->second.nCreateTime); create_time = FormatISO8601DateTime(it->second.nCreateTime);
} }
if(pwallet->GetCScript(scriptid, script)) { if(pwallet->GetCScript(scriptid, script)) {
file << strprintf("%s %s script=1", HexStr(script.begin(), script.end()), create_time); file << strprintf("%s %s script=1", HexStr(script.begin(), script.end()), create_time);

View file

@ -13,7 +13,7 @@ import re
import sys import sys
# Matches on the date format at the start of the log event # 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']) LogEvent = namedtuple('LogEvent', ['timestamp', 'source', 'event'])

View file

@ -358,7 +358,7 @@ class BitcoinTestFramework():
ll = int(self.options.loglevel) if self.options.loglevel.isdigit() else self.options.loglevel.upper() ll = int(self.options.loglevel) if self.options.loglevel.isdigit() else self.options.loglevel.upper()
ch.setLevel(ll) ch.setLevel(ll)
# Format logs the same as bitcoind's debug.log with microprecision (so log files can be concatenated and sorted) # 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 formatter.converter = time.gmtime
fh.setFormatter(formatter) fh.setFormatter(formatter)
ch.setFormatter(formatter) ch.setFormatter(formatter)