util: Print timestamp strings in logs using ISO 8601 formatting #12567

practicalswift · 2018-02-28T15:57:35Z

Print timestamp strings in logs 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.

Before this patch:

2018-02-28 12:34:56 New outbound peer connected: version: 70015, blocks=1286123, peer=0

After this patch:

2018-02-28T12:34:56Z New outbound peer connected: version: 70015, blocks=1286123, peer=0

randolf

In "%Y-%m-%dT%H:%M:%S" it looks like the Timezone (%Z) might be missing.

Optional: Also, consider using %T instead of %H%M%S if it's supported.

randolf · 2018-02-28T16:05:54Z

If you want to use ISO formatting though, then perhaps get rid of the dashes and the colons while you're at it so that it looks like this?

20180228T123456Z

practicalswift · 2018-02-28T18:41:34Z

@randolf The Z is added three lines down. Removing the dashes and colons them would reduce readability, so I'd like to keep them around.

randolf · 2018-02-28T21:39:36Z

@practicalswift Ah, yes, I see it now. Thanks.

laanwj · 2018-03-01T10:12:22Z

Concept ACK.

When changing the log timestamp format you will need to update some of the testing infrastructure, though, such as test/functional/combine_logs.py. This combines logs from bitcoind with logs from the test framework itself, which then should also use the new format.

Removing the dashes and colons them would reduce readability, so I'd like to keep them around.

The ISO formatting allows for them, right? I'd also vote for keeping them.

practicalswift · 2018-03-01T10:33:22Z

@laanwj Thanks for reviewing!

I'll take a look at combine_logs.py.

Yes, 2018-02-28T12:34:56Z (with dashes and colons) is valid according to ISO 8601 :-)

laanwj · 2018-03-05T17:50:24Z

This needs mention in the release notes too; some people might be using scripts that parse the log output that rely on a specific format.

randolf · 2018-03-06T05:58:10Z

@laanwj I agree. Perhaps a custom log formatting option is in order for the long-run? I could probably tackle this after this PR is closed.

laanwj · 2018-03-06T14:15:57Z

@randolf Could be, though personally I'd prefer to not add any more configurability to the log format (there is already -logtimestamps, -logtimemicros). This is all more option combinations that need to be maintained.

In my opinion switching to a standard format (ISO 8601) seems a valid one-time move to do in the next major release. If anything it makes parsing easier because there are existing libraries to parse these. Just needs to be mentioned.

practicalswift · 2018-03-06T14:42:01Z

I agree with @laanwj here. I'm not sure more configurability is better in this case.

@laanwj Can I do something to make sure a note is added to the 0.17.0 release notes? Is there a file that I can edit now or what is the procedure? :-)

laanwj · 2018-03-06T14:47:40Z

@laanwj Can I do something to make sure a note is added to the 0.17.0 release notes? Is there a file that I can edit now or what is the procedure? :-)

Sure - standard procedure is to just add an item to doc/release-notes.md, under notable changes.

practicalswift · 2018-03-06T14:48:31Z

@laanwj Excellent! I'll do that and adjust the TIMESTAMP_PATTERN in test/functional/combine_logs.py.

practicalswift · 2018-03-06T15:20:04Z

Updated. Please review :-)

laanwj · 2018-03-06T15:25:32Z

You didn't update the log setup in test_framework.py:

        # 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')

practicalswift · 2018-03-06T15:32:15Z

@laanwj Oh, sorry about that. Now fixed. Please re-review :-)

practicalswift · 2018-03-06T15:56:29Z

@laanwj Would it make sense to add the following patch to this PR in order to make the switch to ISO 8601 complete, or is that a subject for a follow-up PR?

diff --git a/src/init.cpp b/src/init.cpp
index 1cc5c5f..09702cd 100644
--- a/src/init.cpp
+++ b/src/init.cpp
@@ -1223,7 +1223,7 @@ bool AppInitMain()
     }

     if (!fLogTimestamps)
-        LogPrintf("Startup time: %s\n", DateTimeStrFormat("%Y-%m-%d %H:%M:%S", GetTime()));
+        LogPrintf("Startup time: %s\n", DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", 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 2019146..c439768 100644
--- a/src/net.cpp
+++ b/src/net.cpp
@@ -2782,7 +2782,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, DateTimeStrFormat("%H:%M:%SZ", 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 bc69d4f..57075ee 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(DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", (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 463bed5..c21cfde 100644
--- a/src/test/util_tests.cpp
+++ b/src/test/util_tests.cpp
@@ -98,6 +98,7 @@ 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("%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");
 }
diff --git a/src/util.cpp b/src/util.cpp
index 76aa1c0..71333c3 100644
--- a/src/util.cpp
+++ b/src/util.cpp
@@ -320,7 +320,7 @@ static std::string LogTimestampStr(const std::string &str, std::atomic_bool *fSt
         strStamped += "Z";
         int64_t mocktime = GetMockTime();
         if (mocktime) {
-            strStamped += " (mocktime: " + DateTimeStrFormat("%Y-%m-%d %H:%M:%S", mocktime) + ")";
+            strStamped += " (mocktime: " + DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", mocktime) + ")";
         }
         strStamped += ' ' + str;
     } else
diff --git a/src/validation.cpp b/src/validation.cpp
index d2438b0..0c7e378 100644
--- a/src/validation.cpp
+++ b/src/validation.cpp
@@ -1267,13 +1267,13 @@ 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",
+      log(pindexNew->nChainWork.getdouble())/log(2.0), DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ",
       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()));
+      DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", tip->GetBlockTime()));
     CheckForkWarningConditions();
 }

@@ -2179,7 +2179,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()),
+      DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", pindexNew->GetBlockTime()),
       GuessVerificationProgress(chainParams.TxData(), pindexNew), pcoinsTip->DynamicMemoryUsage() * (1.0 / (1<<20)), pcoinsTip->GetCacheSize());
     if (!warningMessages.empty())
         LogPrintf(" warning='%s'", boost::algorithm::join(warningMessages, ", "));
@@ -3804,7 +3804,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()),
+        DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", chainActive.Tip()->GetBlockTime()),
         GuessVerificationProgress(chainparams.TxData(), chainActive.Tip()));
     return true;
 }

laanwj · 2018-03-06T15:56:30Z

utACK 518820b

laanwj · 2018-03-06T16:01:21Z

@practicalswift sure - let's do that at once - though if we want to enforce a single format throughout the codebase, why not factor out the DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", timespec) to a FormatISO8601 function?
Note that we have a function like that in src/wallet/rpcdump.cpp:

std::string static EncodeDumpTime(int64_t nTime) {
    return DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", nTime);
}

But let's rename and move it to src/utiltime where it belongs [and consistently use it].

practicalswift · 2018-03-06T21:40:24Z

Updated. Introduced FormatISO8601{DateTime,Date,Time}(int64_t) which is now used consistently.

DateTimeStrFormat(…) is now only used by FormatISO8601{DateTime,Date,Time}(int64_t) and by the tests:

$ git grep DateTimeStrFormat | grep -vE '^(src/test/util_tests.cpp|src/utiltime)'
$

Please re-review :-)

laanwj · 2018-03-06T22:30:09Z

src/utiltime.cpp

Do ISO 8601 dates require a timezone as well?

Nope they don't :-)

laanwj · 2018-03-06T22:47:40Z

utACK ed802867d

randolf · 2018-03-07T04:31:04Z

utACK.

@laanwj I agree with your recommendation to standardize on the ISO format as I feel that it's the logical choice for use in log files, plus your point about keeping code maintenance simpler provides excellent justification in this case.

randolf

Standardizing on one set of date/time/date+time subroutines is excellent, and also makes it easier for future code to obtain consistently-formatted dates and times with less effort.

…6Z") * 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.

practicalswift · 2018-03-09T14:02:30Z

Rebased! Please re-review :-)

sipa · 2018-03-09T17:50:52Z

utACK a7324bd

…rmatting a7324bd Format timestamps using ISO 8601 formatting (e.g. "2018-02-28T12:34:56Z") (practicalswift) Pull request description: Print timestamp strings in logs using [ISO 8601](https://en.wikipedia.org/wiki/ISO_8601) formatting (e.g. `2018-02-28T12:34:56Z`): * `Z` is the zone designator for the zero [UTC](https://en.wikipedia.org/wiki/Coordinated_Universal_Time) 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. Before this patch: ``` 2018-02-28 12:34:56 New outbound peer connected: version: 70015, blocks=1286123, peer=0 ``` After this patch: ``` 2018-02-28T12:34:56Z New outbound peer connected: version: 70015, blocks=1286123, peer=0 ``` Tree-SHA512: 52b53c3d3d11ddf4af521a3b5f90a79f6e6539ee5955ec56a5aa2c6a5cf29cecf166d8cb43277c62553c3325a31bcea83691acbb4e86429c523f8aff8d7b210a

…8601 formatting a7324bd Format timestamps using ISO 8601 formatting (e.g. "2018-02-28T12:34:56Z") (practicalswift) Pull request description: Print timestamp strings in logs using [ISO 8601](https://en.wikipedia.org/wiki/ISO_8601) formatting (e.g. `2018-02-28T12:34:56Z`): * `Z` is the zone designator for the zero [UTC](https://en.wikipedia.org/wiki/Coordinated_Universal_Time) 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. Before this patch: ``` 2018-02-28 12:34:56 New outbound peer connected: version: 70015, blocks=1286123, peer=0 ``` After this patch: ``` 2018-02-28T12:34:56Z New outbound peer connected: version: 70015, blocks=1286123, peer=0 ``` Tree-SHA512: 52b53c3d3d11ddf4af521a3b5f90a79f6e6539ee5955ec56a5aa2c6a5cf29cecf166d8cb43277c62553c3325a31bcea83691acbb4e86429c523f8aff8d7b210a Signed-off-by: pasta <[email protected]>

f3f3d6c util: fix compilation with mingw-w64 7.0.0 (Fuzzbawls) f24da7d util: Avoid potential uninitialized read in FormatISO8601DateTime (Fuzzbawls) 120a12a util: Add type safe GetTime (Fuzzbawls) be48766 Fix for utiltime to compile with msvc. (Aaron Clauson) 2833406 Avoid std::locale/imbue in DateTimeStrFormat (Pieter Wuille) 3331c25 Format automatic wallet backup file names in ISO 8601 basic format (Fuzzbawls) c32a208 Format timestamps using ISO 8601 formatting (e.g. "2018-02-28T12:34:56Z") (practicalswift) f8bd173 [logging] log system time and mock time (John Newbery) Pull request description: This is a backport of a collection of upstream PRs to bring our time utility more up to date. The following upstream PRs are included: - bitcoin#10383 - bitcoin#12567 - bitcoin#12973 - bitcoin#13031 - bitcoin#16046 - bitcoin#18162 - bitcoin#18358 The two user-facing notable changes here have been documented in the release notes template. I've also connected the functionality that `-logtimemicros` was supposed to provide. ACKs for top commit: furszy: code review ACK f3f3d6c random-zebra: utACK f3f3d6c after rebase, and merging... Tree-SHA512: 64f9cc1f7fc65c192f3b3ab869c057a81e007cf0fae82ecd23993c6b51830e4bc80656c699ba40bb8e019115a24d1ea88a618be0c0d7112749d9ce125d62ce44

…8601 formatting a7324bd Format timestamps using ISO 8601 formatting (e.g. "2018-02-28T12:34:56Z") (practicalswift) Pull request description: Print timestamp strings in logs using [ISO 8601](https://en.wikipedia.org/wiki/ISO_8601) formatting (e.g. `2018-02-28T12:34:56Z`): * `Z` is the zone designator for the zero [UTC](https://en.wikipedia.org/wiki/Coordinated_Universal_Time) 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. Before this patch: ``` 2018-02-28 12:34:56 New outbound peer connected: version: 70015, blocks=1286123, peer=0 ``` After this patch: ``` 2018-02-28T12:34:56Z New outbound peer connected: version: 70015, blocks=1286123, peer=0 ``` Tree-SHA512: 52b53c3d3d11ddf4af521a3b5f90a79f6e6539ee5955ec56a5aa2c6a5cf29cecf166d8cb43277c62553c3325a31bcea83691acbb4e86429c523f8aff8d7b210a Signed-off-by: pasta <[email protected]>

practicalswift changed the title ~~Print timestamp strings in logs using ISO 8601 formatting~~ util: Print timestamp strings in logs using ISO 8601 formatting Feb 28, 2018

randolf suggested changes Feb 28, 2018

View reviewed changes

randolf approved these changes Feb 28, 2018

View reviewed changes

fanquake added the Utils/log/libs label Mar 1, 2018

laanwj added this to the 0.17.0 milestone Mar 6, 2018

practicalswift force-pushed the iso-8601 branch from c8bf801 to 81e8ee6 Compare March 6, 2018 15:19

practicalswift force-pushed the iso-8601 branch from 81e8ee6 to 518820b Compare March 6, 2018 15:31

practicalswift force-pushed the iso-8601 branch 2 times, most recently from 2c7496b to ed80286 Compare March 6, 2018 21:29

laanwj reviewed Mar 6, 2018

View reviewed changes

randolf approved these changes Mar 7, 2018

View reviewed changes

practicalswift force-pushed the iso-8601 branch from ed80286 to a7324bd Compare March 9, 2018 14:02

laanwj merged commit a7324bd into bitcoin:master Mar 10, 2018

Fuzzbawls mentioned this pull request Apr 8, 2021

[Util] Time utility updates PIVX-Project/PIVX#2300

Merged

practicalswift deleted the iso-8601 branch April 10, 2021 19:33

bitcoin locked as resolved and limited conversation to collaborators Aug 18, 2022

util: Print timestamp strings in logs using ISO 8601 formatting #12567

util: Print timestamp strings in logs using ISO 8601 formatting #12567

Uh oh!

Conversation

practicalswift commented Feb 28, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

randolf left a comment

Choose a reason for hiding this comment

Uh oh!

randolf commented Feb 28, 2018

Uh oh!

practicalswift commented Feb 28, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

randolf commented Feb 28, 2018

Uh oh!

laanwj commented Mar 1, 2018

Uh oh!

practicalswift commented Mar 1, 2018

Uh oh!

laanwj commented Mar 5, 2018

Uh oh!

randolf commented Mar 6, 2018

Uh oh!

laanwj commented Mar 6, 2018

Uh oh!

practicalswift commented Mar 6, 2018

Uh oh!

laanwj commented Mar 6, 2018

Uh oh!

practicalswift commented Mar 6, 2018

Uh oh!

practicalswift commented Mar 6, 2018

Uh oh!

laanwj commented Mar 6, 2018

Uh oh!

practicalswift commented Mar 6, 2018

Uh oh!

practicalswift commented Mar 6, 2018

Uh oh!

laanwj commented Mar 6, 2018

Uh oh!

laanwj commented Mar 6, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

practicalswift commented Mar 6, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

laanwj Mar 6, 2018

Choose a reason for hiding this comment

Uh oh!

practicalswift Mar 6, 2018

Choose a reason for hiding this comment

Uh oh!

laanwj commented Mar 6, 2018

Uh oh!

randolf commented Mar 7, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

randolf left a comment

Choose a reason for hiding this comment

Uh oh!

practicalswift commented Mar 9, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

sipa commented Mar 9, 2018

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

practicalswift commented Feb 28, 2018 •

edited

Loading

practicalswift commented Feb 28, 2018 •

edited

Loading

laanwj commented Mar 6, 2018 •

edited

Loading

practicalswift commented Mar 6, 2018 •

edited

Loading

randolf commented Mar 7, 2018 •

edited

Loading

practicalswift commented Mar 9, 2018 •

edited

Loading