diff --git a/src/picologging/formatter.cxx b/src/picologging/formatter.cxx index c394569..fa6a7dd 100644 --- a/src/picologging/formatter.cxx +++ b/src/picologging/formatter.cxx @@ -1,10 +1,16 @@ #include #include +#include #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(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(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(createdFrac * 1e3)); asctime = PyUnicode_FromStringAndSize(buf, len); } @@ -354,4 +400,4 @@ PyTypeObject FormatterType = { 0, /* tp_alloc */ Formatter_new, /* tp_new */ PyObject_Del, /* tp_free */ -}; +}; \ No newline at end of file diff --git a/src/picologging/formatter.hxx b/src/picologging/formatter.hxx index 5f0a0b9..8541d13 100644 --- a/src/picologging/formatter.hxx +++ b/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; diff --git a/tests/unit/test_formatter.py b/tests/unit/test_formatter.py index 15eccee..503a214 100644 --- a/tests/unit/test_formatter.py +++ b/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")