Add support for %f (format microseconds) to datefmt

src/picologging/formatter.cxx

@@ -1,10 +1,16 @@
 #include <ctime>
 #include <charconv>
+#include <string_view>
 #include "picologging.hxx"
 #include "formatter.hxx"
 #include "formatstyle.hxx"
 #include "logrecord.hxx"
 
+// Size of the temporary buffer on stack to format asctime.
+// 64 - is big enough.
+// For example: "2024-07-23 03:27:04.982856" - is just 29 bytes
+constexpr const size_t MAX_FORMATTED_ASCTIME_SIZE = 64;
+
 PyObject* Formatter_new(PyTypeObject* type, PyObject* args, PyObject* kwds)
 {
     Formatter* self = (Formatter*)type->tp_alloc(type, 0);
@@ -63,13 +69,26 @@ int Formatter_init(Formatter *self, PyObject *args, PyObject *kwds){
     self->usesTime = (FormatStyle_usesTime((FormatStyle*)self->style) == Py_True);
     self->dateFmt = Py_NewRef(dateFmt);
 
+    self->_dateFmtMicrosendsPos = std::string_view::npos;
+    self->_dateFmtStrSize = 0;
     if (dateFmt != Py_None) {
-        self->dateFmtStr = PyUnicode_AsUTF8(self->dateFmt);
-        if (self->dateFmtStr == nullptr) {
+        self->_dateFmtStr = PyUnicode_AsUTF8(self->dateFmt);
+        if (self->_dateFmtStr == nullptr) {
             return -1;
         }
+        std::string_view dateFmtSV = self->_dateFmtStr;
+        self->_dateFmtStrSize = dateFmtSV.size();
+
+        // Later we use temporary buffer allocated on stack to format %f before using standard strftime
+        // This check protects against buffer overflow. If dateFmt is too large for the buffer
+        // (bigger than in this check) then %f formatting will be disabled thus dateFmt will be passed
+        // directly to strftime.
+        // -6 means we need extra space for 6 digits of microseconds
+        // +2 we reuse 2 digits of %f specifier
+        if (self->_dateFmtStrSize <= MAX_FORMATTED_ASCTIME_SIZE - 6 + 2)
+            self->_dateFmtMicrosendsPos = dateFmtSV.find("%f");
     } else {
-        self->dateFmtStr = nullptr;
+        self->_dateFmtStr = nullptr;
     }
 
     if (validate){
@@ -92,17 +111,44 @@ PyObject* Formatter_format(Formatter *self, PyObject *record){
         if (self->usesTime){
             PyObject * asctime = Py_None;
             double createdInt;
-            int createdFrac = std::modf(logRecord->created, &createdInt) * 1e3;
+            double createdFrac = std::modf(logRecord->created, &createdInt);
             std::time_t created = static_cast<std::time_t>(createdInt);
             std::tm *ct = localtime(&created);
+
+            // Buffer for formatted asctime
+            char buf[MAX_FORMATTED_ASCTIME_SIZE + 1];
+
             if (self->dateFmt != Py_None){
-                char buf[100];
-                size_t len = strftime(buf, sizeof(buf), self->dateFmtStr, ct);
+                // dateFmt has been specified for asctime
+                size_t len = [&](){
+                    if (self->_dateFmtMicrosendsPos != std::string_view::npos){
+                        // There is %f in it the provided dateFmt.
+                        // Prepare format string for strftime where %f will
+                        // be replaced with the actual microseconds
+                        char formatStrBuf[MAX_FORMATTED_ASCTIME_SIZE + 1];
+
+                        // Copy everything before %f
+                        memcpy(formatStrBuf, self->_dateFmtStr, self->_dateFmtMicrosendsPos);
+                        // Format microseconds
+                        snprintf(formatStrBuf + self->_dateFmtMicrosendsPos,
+                                 sizeof(formatStrBuf) - 1, "%06d",
+                                 static_cast<int>(std::round(createdFrac * 1e6)));
+                        // Copy everthing after %f, including null terminator
+                        memcpy(formatStrBuf + self->_dateFmtMicrosendsPos + 6,
+                               self->_dateFmtStr + self->_dateFmtMicrosendsPos + 2,
+                               self->_dateFmtStrSize - self->_dateFmtMicrosendsPos - 2 + 1);
+
+                        return strftime(buf, sizeof(buf), formatStrBuf, ct);
+                    } else {
+                        return strftime(buf, sizeof(buf), self->_dateFmtStr, ct);
+                    }
+                }();
+
                 asctime = PyUnicode_FromStringAndSize(buf, len);
             } else {
-                char buf[100];
+                // dateFmt has not been specified for asctime, use default formatting
                 size_t len = strftime(buf, sizeof(buf), "%F %T" , ct);
-                len += snprintf(buf + len, sizeof(buf) - len, ",%03d", createdFrac);
+                len += snprintf(buf + len, sizeof(buf) - len, ",%03d", static_cast<int>(createdFrac * 1e3));
                 asctime = PyUnicode_FromStringAndSize(buf, len);
             }
 
@@ -354,4 +400,4 @@ PyTypeObject FormatterType = {
     0,                                          /* tp_alloc */
     Formatter_new,                          /* tp_new */
     PyObject_Del,                               /* tp_free */
-};
+};

src/picologging/formatter.hxx

@@ -12,7 +12,9 @@ typedef struct {
     PyObject *dateFmt;
     PyObject *style;
     bool usesTime;
-    const char* dateFmtStr;
+    size_t _dateFmtMicrosendsPos;        // If %f is specified in dateFmt then points to '%' character, otherwise std::string_view::npos
+    size_t _dateFmtStrSize;              // Size of the dateFmt without null terminator
+    const char* _dateFmtStr;             // dateFmt as a C-string, null terminated
     PyObject *_const_line_break;
     PyObject *_const_close;
     PyObject *_const_getvalue;

tests/unit/test_formatter.py

@@ -263,6 +263,22 @@ def test_format_with_custom_datefmt():
     assert f.formatMessage(record) == s
 
 
+@pytest.mark.limit_leaks("192B", filter_fn=filter_gc)
+def test_format_with_custom_datefmt_and_microseconds_specifier():
+    f = Formatter(
+        "%(name)s %(levelname)s %(message)s %(asctime)s bork", datefmt="%F %T,%f"
+    )
+    assert f.datefmt == "%F %T,%f"
+    record = LogRecord(
+        "hello", logging.WARNING, __file__, 123, "bork bork bork", (), None
+    )
+    s = f.format(record)
+    actual_date = datetime.datetime.fromtimestamp(record.created).strftime("%F %T,%f")
+    assert s == f"hello WARNING bork bork bork {actual_date} bork"
+    assert f.usesTime() is True
+    assert f.formatMessage(record) == s
+
+
 @pytest.mark.limit_leaks("192B", filter_fn=filter_gc)
 def test_formatter_repr():
     f = Formatter("%(message)s")