SERVER-45755 Special formatting for duration type in logv2

Unit suffix gets appended to attribute name when creating JSON field name.

8 files changed, 136 insertions, 20 deletions

diff --git a/src/mongo/logv2/README.md b/src/mongo/logv2/README.md
index 14166234c66..3ba78458a46 100644
--- a/src/mongo/logv2/README.md
+++ b/src/mongo/logv2/README.md
@@ -32,7 +32,7 @@ Libfmt supports named replacement fields within the message string, this is not
 
 The message string must be a compile time constant. This is to be able to add compile time verification of log statements in the future.
 
-#### Examples
+##### Examples
 
 ```
 LOGV2(1000, "Logging event, no replacement fields is OK");
@@ -54,7 +54,7 @@ To override the default component, a separate logging API can be used that takes
 
 `LogOptions` can be constructed with a `LogComponent` to avoid verbosity in the log statement.
 
-#### Examples
+##### Examples
 
 ```
 LOGV2_OPTIONS(1003, {LogComponent::kCommand}, "Log event to specified component");
@@ -82,7 +82,7 @@ Debug-level logging is slightly different where an additional parameter (as inte
 
 `LOGV2_DEBUG_OPTIONS(ID, debug-level, options, message-string, attr0, ..., attrN);`
 
-#### Examples
+##### Examples
 
 ```
 // Index specifier in replacement field
@@ -99,7 +99,7 @@ Tags are added to a log statement with the options API similarly to how non-defa
 
 Multiple tags can be attached to a log statement using the bitwise or operator `|`.
 
-#### Examples
+##### Examples
 
 ```
 LOGV2_WARNING_OPTIONS(1005, {LogTag::kStartupWarnings}, "XFS filesystem is recommended with WiredTiger");
@@ -122,6 +122,8 @@ Many basic types have built in support:
   * std::string
   * StringData
   * const char*
+* Duration types
+  * Special formatting, see below
 * BSON types
   * BSONObj
   * BSONArray
@@ -165,7 +167,7 @@ Enums will only try to bind a `toString(const T& val)` non-member function. If o
 
 *NOTE: No `operator<<` overload is used even if available*
 
-#### Examples
+##### Examples
 
 ```
 class UserDefinedType {
@@ -209,7 +211,7 @@ seqLog indicates that it is a sequential range where the iterators point to logg
 mapLog indicates that it is a range coming from an associative container where the iterators point to a key-value pair.
 
 
-#### Examples
+##### Examples
 
 ```
 std::array<int, 20> arrayOfInts = ...;
@@ -224,6 +226,31 @@ LOGV2(1013, "log map directly: {}", "values"_attr = bsonMap);
 LOGV2(1014, "log map iterator range: {}", "values"_attr = mapLog(bsonMap.begin(), bsonMap.end());
 ``` 
 
+### Duration types
+
+Duration types have special formatting to match existing practices in the server code base. Their resulting format depends on the context they are logged.
+
+When durations are formatted as JSON or BSON a unit suffix is added to the attribute name when building the field name. The value will be count of the duration as a number.
+
+When logging containers with durations there is no attribute per duration instance that can have the suffix added. In this case durations are instead formatted as a BSON object.
+
+##### Examples
+
+`"duration"_attr = Milliseconds(10)`
+
+Text | JSON/BSON
+---- | ---------
+`10 ms` | `"durationMillis": 10`
+
+```
+std::vector<Nanoseconds> nanos = {Nanoseconds(200), Nanoseconds(400)};
+"samples"_attr = nanos
+```
+
+Text | JSON/BSON
+---- | ---------
+`(200 ns, 400 ns)` | `"samples": [{"durationNanos": 200}, {"durationNanos": 400}]`
+
 # Output formats
 
 Desired log output format is set to mongod, mongos and the mongo shell using the `-logFormat` option. Available values are `text` and `json`. Currently text formatting is default.
diff --git a/src/mongo/logv2/attribute_storage.h b/src/mongo/logv2/attribute_storage.h
index 22bcfdb006b..a3d7409e649 100644
--- a/src/mongo/logv2/attribute_storage.h
+++ b/src/mongo/logv2/attribute_storage.h
@@ -33,6 +33,7 @@
 #include "mongo/bson/bsonobjbuilder.h"
 #include "mongo/logv2/constants.h"
 #include "mongo/stdx/variant.h"
+#include "mongo/util/duration.h"
 
 #include <functional>
 
@@ -66,7 +67,6 @@ template <typename It>
 auto mapLog(It begin, It end);
 
 namespace detail {
-namespace {
 
 // Helper traits to figure out capabilities on custom types
 template <class T>
@@ -75,6 +75,12 @@ struct IsOptional : std::false_type {};
 template <class T>
 struct IsOptional<boost::optional<T>> : std::true_type {};
 
+template <class T>
+struct IsDuration : std::false_type {};
+
+template <class T>
+struct IsDuration<Duration<T>> : std::true_type {};
+
 template <class T, typename = void>
 struct IsContainer : std::false_type {};
 
@@ -154,8 +160,6 @@ struct HasNonMemberToBSON : std::false_type {};
 template <class T>
 struct HasNonMemberToBSON<T, std::void_t<decltype(toBSON(std::declval<T>()))>> : std::true_type {};
 
-}  // namespace
-
 // Mapping functions on how to map a logged value to how it is stored in variant (reused by
 // container support)
 inline bool mapValue(bool value) {
@@ -220,6 +224,11 @@ inline CustomAttributeValue mapValue(boost::none_t val) {
     return custom;
 }
 
+template <typename T, std::enable_if_t<IsDuration<T>::value, int> = 0>
+auto mapValue(T val) {
+    return val;
+}
+
 template <typename T, std::enable_if_t<std::is_enum_v<T>, int> = 0>
 auto mapValue(T val) {
     if constexpr (HasNonMemberToString<T>::value) {
@@ -247,10 +256,11 @@ CustomAttributeValue mapValue(const T& val) {
     return custom;
 }
 
-template <typename T,
-          std::enable_if_t<!std::is_integral_v<T> && !std::is_floating_point_v<T> &&
-                               !std::is_enum_v<T> && !IsContainer<T>::value,
-                           int> = 0>
+template <
+    typename T,
+    std::enable_if_t<!std::is_integral_v<T> && !std::is_floating_point_v<T> && !std::is_enum_v<T> &&
+                         !IsDuration<T>::value && !IsContainer<T>::value,
+                     int> = 0>
 CustomAttributeValue mapValue(const T& val) {
     static_assert(HasToString<T>::value || HasStringSerialize<T>::value ||
                       HasNonMemberToString<T>::value,
@@ -315,6 +325,8 @@ public:
                     } else {
                         builder.append(val.toString());
                     }
+                } else if constexpr (IsDuration<std::decay_t<decltype(val)>>::value) {
+                    builder.append(val.toBSON());
                 } else {
                     builder.append(val);
                 }
@@ -349,6 +361,9 @@ public:
                     } else {
                         fmt::format_to(buffer, "{}", val.toString());
                     }
+
+                } else if constexpr (IsDuration<std::decay_t<decltype(val)>>::value) {
+                    fmt::format_to(buffer, "{}", val.toString());
                 } else {
                     fmt::format_to(buffer, "{}", val);
                 }
@@ -404,6 +419,8 @@ public:
                     } else {
                         builder->append(key, val.toString());
                     }
+                } else if constexpr (IsDuration<std::decay_t<decltype(val)>>::value) {
+                    builder->append(key, val.toBSON());
                 } else {
                     builder->append(key, val);
                 }
@@ -438,6 +455,8 @@ public:
                     } else {
                         fmt::format_to(buffer, "{}: {}", key, val.toString());
                     }
+                } else if constexpr (IsDuration<std::decay_t<decltype(val)>>::value) {
+                    fmt::format_to(buffer, "{}: {}", key, val.toString());
                 } else {
                     fmt::format_to(buffer, "{}: {}", key, val);
                 }
@@ -491,6 +510,13 @@ public:
                   bool,
                   double,
                   StringData,
+                  Nanoseconds,
+                  Microseconds,
+                  Milliseconds,
+                  Seconds,
+                  Minutes,
+                  Hours,
+                  Days,
                   const BSONObj*,
                   const BSONArray*,
                   CustomAttributeValue>
diff --git a/src/mongo/logv2/bson_formatter.cpp b/src/mongo/logv2/bson_formatter.cpp
index 9ef3017b815..a4488b5b065 100644
--- a/src/mongo/logv2/bson_formatter.cpp
+++ b/src/mongo/logv2/bson_formatter.cpp
@@ -98,6 +98,11 @@ struct BSONValueExtractor {
         _builder.append(name, static_cast<long long>(val));
     }
 
+    template <typename Period>
+    void operator()(StringData name, const Duration<Period>& value) {
+        _builder.append(name.toString() + value.mongoUnitSuffix(), value.count());
+    }
+
     template <typename T>
     void operator()(StringData name, const T& value) {
         _builder.append(name, value);
diff --git a/src/mongo/logv2/json_formatter.cpp b/src/mongo/logv2/json_formatter.cpp
index d70caf693b9..7fecf7c0f62 100644
--- a/src/mongo/logv2/json_formatter.cpp
+++ b/src/mongo/logv2/json_formatter.cpp
@@ -102,6 +102,13 @@ struct JSONValueExtractor {
         storeQuoted(name, value);
     }
 
+    template <typename Period>
+    void operator()(StringData name, const Duration<Period>& value) {
+        fmt::format_to(
+            _buffer, R"({}"{}{}":{})", _separator, name, value.mongoUnitSuffix(), value.count());
+        _separator = ","_sd;
+    }
+
     template <typename T>
     void operator()(StringData name, const T& value) {
         storeUnquotedValue(name, value);
diff --git a/src/mongo/logv2/log_test_v2.cpp b/src/mongo/logv2/log_test_v2.cpp
index 4e722964893..0e9b81cdde6 100644
--- a/src/mongo/logv2/log_test_v2.cpp
+++ b/src/mongo/logv2/log_test_v2.cpp
@@ -573,11 +573,15 @@ TEST_F(LogTestV2, Types) {
     ASSERT_EQUALS(mongo::fromjson(json.back())
                       .getField(kAttributesFieldName)
                       .Obj()
-                      .getField("name")
+                      .getField("name" + ms.mongoUnitSuffix())
+                      .Int(),
+                  ms.count());
+    ASSERT_EQUALS(BSONObj(bson.back().data())
+                      .getField(kAttributesFieldName)
                       .Obj()
-                      .woCompare(ms.toBSON()),
-                  0);
-    ASSERT(lastBSONElement().Obj().woCompare(ms.toBSON()) == 0);
+                      .getField("name" + ms.mongoUnitSuffix())
+                      .Long(),
+                  ms.count());
 }
 
 TEST_F(LogTestV2, TextFormat) {
@@ -990,6 +994,31 @@ TEST_F(LogTestV2, Containers) {
     };
     validateMapOfOptionalVectors(mongo::fromjson(json.back()));
     validateMapOfOptionalVectors(BSONObj(bson.back().data()));
+
+    std::vector<Nanoseconds> nanos = {Nanoseconds(10), Nanoseconds(100)};
+    LOGV2(20081, "{}", "name"_attr = nanos);
+    auto validateDurationVector = [&nanos](const BSONObj& obj) {
+        std::vector<BSONElement> jsonVector =
+            obj.getField(kAttributesFieldName).Obj().getField("name").Array();
+        ASSERT_EQUALS(nanos.size(), jsonVector.size());
+        for (std::size_t i = 0; i < nanos.size(); ++i)
+            ASSERT(jsonVector[i].Obj().woCompare(nanos[i].toBSON()) == 0);
+    };
+    validateDurationVector(mongo::fromjson(json.back()));
+    validateDurationVector(BSONObj(bson.back().data()));
+
+    std::map<std::string, Microseconds> mapOfMicros = {{"first", Microseconds(20)},
+                                                       {"second", Microseconds(40)}};
+    LOGV2(20082, "{}", "name"_attr = mapOfMicros);
+    auto validateMapOfMicros = [&mapOfMicros](const BSONObj& obj) {
+        BSONObj mappedValues = obj.getField(kAttributesFieldName).Obj().getField("name").Obj();
+        auto in = mapOfMicros.begin();
+        for (; in != mapOfMicros.end(); ++in) {
+            ASSERT(mappedValues.getField(in->first).Obj().woCompare(in->second.toBSON()) == 0);
+        }
+    };
+    validateMapOfMicros(mongo::fromjson(json.back()));
+    validateMapOfMicros(BSONObj(bson.back().data()));
 }
 
 TEST_F(LogTestV2, Unicode) {
diff --git a/src/mongo/logv2/plain_formatter.cpp b/src/mongo/logv2/plain_formatter.cpp
index e555d1b90ad..204eb336f0e 100644
--- a/src/mongo/logv2/plain_formatter.cpp
+++ b/src/mongo/logv2/plain_formatter.cpp
@@ -70,6 +70,12 @@ struct TextValueExtractor {
         operator()(name, _storage.back());
     }
 
+    template <typename Period>
+    void operator()(StringData name, const Duration<Period>& val) {
+        _storage.push_back(val.toString());
+        args.push_back(fmt::internal::make_arg<fmt::format_context>(_storage.back()));
+    }
+
     template <typename T>
     void operator()(StringData name, const T& val) {
         args.push_back(fmt::internal::make_arg<fmt::format_context>(val));
diff --git a/src/mongo/util/duration.cpp b/src/mongo/util/duration.cpp
index 44239275d4d..5ac9f025eae 100644
--- a/src/mongo/util/duration.cpp
+++ b/src/mongo/util/duration.cpp
@@ -38,9 +38,7 @@ namespace mongo {
 template <typename Period>
 BSONObj Duration<Period>::toBSON() const {
     BSONObjBuilder builder;
-    builder.append("units", unit_short());
-    builder.append("value", count());
-    builder.done();
+    builder.append("duration" + mongoUnitSuffix(), count());
     return builder.obj();
 }
 
diff --git a/src/mongo/util/duration.h b/src/mongo/util/duration.h
index 4e947ccd4ed..ed187c0ed71 100644
--- a/src/mongo/util/duration.h
+++ b/src/mongo/util/duration.h
@@ -146,6 +146,24 @@ public:
         }
         return StringData{};
     }
+    static constexpr StringData mongoUnitSuffix() {
+        if constexpr (std::is_same_v<Duration, Nanoseconds>) {
+            return "Nanos"_sd;
+        } else if constexpr (std::is_same_v<Duration, Microseconds>) {
+            return "Micros"_sd;
+        } else if constexpr (std::is_same_v<Duration, Milliseconds>) {
+            return "Millis"_sd;
+        } else if constexpr (std::is_same_v<Duration, Seconds>) {
+            return "Seconds"_sd;
+        } else if constexpr (std::is_same_v<Duration, Minutes>) {
+            return "Minutes"_sd;
+        } else if constexpr (std::is_same_v<Duration, Hours>) {
+            return "Hours"_sd;
+        } else if constexpr (std::is_same_v<Duration, Days>) {
+            return "Days"_sd;
+        }
+        return StringData{};
+    }
     MONGO_STATIC_ASSERT_MSG(Period::num > 0, "Duration::period's numerator must be positive");
     MONGO_STATIC_ASSERT_MSG(Period::den > 0, "Duration::period's denominator must be positive");