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

pull practicalswift wants to merge 1 commits into bitcoin:master from practicalswift:iso-8601 changing 12 files +61 −23
  1. practicalswift commented at 3:57 PM on February 28, 2018: contributor

    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
  2. practicalswift renamed this:
    Print timestamp strings in logs using ISO 8601 formatting
    util: Print timestamp strings in logs using ISO 8601 formatting
    on Feb 28, 2018
  3. randolf changes_requested
  4. randolf commented at 4:04 PM on February 28, 2018: contributor

    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.

  5. randolf commented at 4:05 PM on February 28, 2018: contributor

    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

  6. practicalswift commented at 6:41 PM on February 28, 2018: contributor

    @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.

  7. randolf commented at 9:39 PM on February 28, 2018: contributor

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

  8. randolf approved
  9. fanquake added the label Utils/log/libs on Mar 1, 2018
  10. laanwj commented at 10:12 AM on March 1, 2018: member

    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.

  11. practicalswift commented at 10:33 AM on March 1, 2018: contributor

    @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 :-)

  12. laanwj commented at 5:50 PM on March 5, 2018: member

    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.

  13. randolf commented at 5:58 AM on March 6, 2018: contributor

    @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.

  14. laanwj commented at 2:15 PM on March 6, 2018: member

    @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.

  15. laanwj added this to the milestone 0.17.0 on Mar 6, 2018
  16. practicalswift commented at 2:42 PM on March 6, 2018: contributor

    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? :-)

  17. laanwj commented at 2:47 PM on March 6, 2018: member

    @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.

  18. practicalswift commented at 2:48 PM on March 6, 2018: contributor

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

  19. practicalswift force-pushed on Mar 6, 2018
  20. practicalswift commented at 3:20 PM on March 6, 2018: contributor

    Updated. Please review :-)

  21. laanwj commented at 3:25 PM on March 6, 2018: member

    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')
  22. practicalswift force-pushed on Mar 6, 2018
  23. practicalswift commented at 3:32 PM on March 6, 2018: contributor

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

  24. practicalswift commented at 3:56 PM on March 6, 2018: contributor

    @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;
 }
  26. laanwj commented at 4:01 PM on March 6, 2018: member

    @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].

  27. practicalswift force-pushed on Mar 6, 2018
  28. practicalswift force-pushed on Mar 6, 2018
  29. practicalswift commented at 9:40 PM on March 6, 2018: contributor

    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 :-)

  30. in src/utiltime.cpp:94 in ed802867d1 outdated 
      89 | +std::string FormatISO8601DateTime(int64_t nTime) {
  90 | +    return DateTimeStrFormat("%Y-%m-%dT%H:%M:%SZ", nTime);
  91 | +}
  92 | +
  93 | +std::string FormatISO8601Date(int64_t nTime) {
  94 | +    return DateTimeStrFormat("%Y-%m-%d", nTime);
    laanwj commented at 10:30 PM on March 6, 2018:

    Do ISO 8601 dates require a timezone as well?

    practicalswift commented at 10:32 PM on March 6, 2018:

    Nope they don't :-)

  31. laanwj commented at 10:47 PM on March 6, 2018: member

    utACK ed802867d

  32. randolf commented at 4:31 AM on March 7, 2018: contributor

    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.

  33. randolf approved
  34. randolf commented at 4:34 AM on March 7, 2018: contributor

    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.

  35. 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.
    a7324bd799
  36. practicalswift force-pushed on Mar 9, 2018
  37. practicalswift commented at 2:02 PM on March 9, 2018: contributor

    Rebased! Please re-review :-)

  38. sipa commented at 5:50 PM on March 9, 2018: member

    utACK a7324bd799591546c2ae069f29cb82a66d427769

  39. laanwj merged this on Mar 10, 2018
  40. laanwj closed this on Mar 10, 2018
  41. laanwj referenced this in commit bb98aec674 on Mar 10, 2018
  42. PastaPastaPasta referenced this in commit 2564c17330 on Dec 16, 2020
  43. PastaPastaPasta referenced this in commit 603ac552c6 on Dec 18, 2020
  44. practicalswift deleted the branch on Apr 10, 2021
  45. random-zebra referenced this in commit 14060430d9 on May 5, 2021
  46. gades referenced this in commit 0baa079e96 on Mar 13, 2022
  47. DrahtBot locked this on Aug 18, 2022
Contributors
practicalswiftrandolflaanwjsipa
Labels
Utils/log/libs

Milestone
0.17.0

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2026-04-13 15:15 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me