Merge pull request #208 from tarasko/main

Fix asctime formatting, don't print uninitialized buffer's content (issue #203)

Author: tonybaloney

src/picologging/__init__.py

@@ -177,7 +177,9 @@ def setLoggerClass(self, klass):
         self.cls = klass
 
     def setLogRecordFactory(self, factory):
-        raise NotImplementedError("setLogRecordFactory is not supported in picologging.")
+        raise NotImplementedError(
+            "setLogRecordFactory is not supported in picologging."
+        )
 
 
 root = Logger(name="root", level=WARNING)

src/picologging/formatter.cxx

@@ -1,4 +1,5 @@
 #include <ctime>
+#include <charconv>
 #include "picologging.hxx"
 #include "formatter.hxx"
 #include "formatstyle.hxx"
@@ -90,15 +91,19 @@ PyObject* Formatter_format(Formatter *self, PyObject *record){
         }
         if (self->usesTime){
             PyObject * asctime = Py_None;
-            std::time_t created = (std::time_t)logRecord->created;
+            double createdInt;
+            int createdFrac = std::modf(logRecord->created, &createdInt) * 1e3;
+            std::time_t created = static_cast<std::time_t>(createdInt);
             std::tm *ct = localtime(&created);
             if (self->dateFmt != Py_None){
                 char buf[100];
-                size_t len = strftime(buf, 100, self->dateFmtStr, ct);
+                size_t len = strftime(buf, sizeof(buf), self->dateFmtStr, ct);
                 asctime = PyUnicode_FromStringAndSize(buf, len);
             } else {
                 char buf[100];
-                asctime = PyUnicode_FromFormat("%s,%03d", buf, logRecord->msecs);
+                size_t len = strftime(buf, sizeof(buf), "%F %T" , ct);
+                len += snprintf(buf + len, sizeof(buf) - len, ",%03d", createdFrac);
+                asctime = PyUnicode_FromStringAndSize(buf, len);
             }
 
             Py_XDECREF(logRecord->asctime);
@@ -349,4 +354,4 @@ PyTypeObject FormatterType = {
     0,                                          /* tp_alloc */
     Formatter_new,                          /* tp_new */
     PyObject_Del,                               /* tp_free */
-};
+};

tests/unit/test_formatter.py

@@ -3,6 +3,7 @@
 import logging
 import sys
 import traceback
+from logging import Formatter as LoggingFormatter
 
 import pytest
 from utils import filter_gc
@@ -147,6 +148,18 @@ def test_asctime_field():
     assert pico_f.usesTime()
 
 
+@pytest.mark.limit_leaks("192B", filter_fn=filter_gc)
+def test_asctime_field_buffer():
+    pico_f = Formatter("%(asctime)s")
+    record = LogRecord(
+        "hello", logging.WARNING, __file__, 123, "bork bork bork", (), None
+    )
+    logging_f = LoggingFormatter("%(asctime)s")
+
+    assert pico_f.format(record).split(",")[0] == logging_f.format(record).split(",")[0]
+    assert pico_f.usesTime()
+
+
 @pytest.mark.limit_leaks("192B", filter_fn=filter_gc)
 def test_record_with_stack_info():
     pico_f = Formatter("%(message)s")