diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 2fa2ab768dc48b..303615e32e9ed4 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -251,6 +251,7 @@ jobs: bolt-optimizations: ${{ matrix.bolt }} free-threading: ${{ matrix.free-threading }} os: ${{ matrix.os }} + traceback_timestamps: ${{ matrix.os == 'ubuntu-24.04-arm' && matrix.bolt == false && 'ns' || '' }} test-opts: ${{ matrix.test-opts || '' }} build-ubuntu-ssltests: @@ -708,3 +709,4 @@ jobs: ${{ !fromJSON(needs.build-context.outputs.run-ios) && 'build-ios,' || '' }} ${{ !fromJSON(needs.build-context.outputs.run-wasi) && 'build-wasi,' || '' }} jobs: ${{ toJSON(needs) }} + traceback_timestamps: 'iso' diff --git a/.github/workflows/reusable-macos.yml b/.github/workflows/reusable-macos.yml index 6afbf6595d93e3..5f785cf77cb907 100644 --- a/.github/workflows/reusable-macos.yml +++ b/.github/workflows/reusable-macos.yml @@ -11,6 +11,10 @@ on: description: OS to run the job required: true type: string + traceback_timestamps: + description: Set to us|1|ns|iso to enable printing timestamps on exceptions in tracebacks (for feature coverage) + required: false + type: string env: FORCE_COLOR: 1 @@ -26,6 +30,7 @@ jobs: HOMEBREW_NO_INSTALL_CLEANUP: 1 HOMEBREW_NO_INSTALLED_DEPENDENTS_CHECK: 1 PYTHONSTRICTEXTENSIONBUILD: 1 + PYTHON_TRACEBACK_TIMESTAMPS: ${{ inputs.traceback_timestamps }} TERM: linux steps: - uses: actions/checkout@v6 diff --git a/.github/workflows/reusable-ubuntu.yml b/.github/workflows/reusable-ubuntu.yml index 6464590dee4776..36dac52bb203ad 100644 --- a/.github/workflows/reusable-ubuntu.yml +++ b/.github/workflows/reusable-ubuntu.yml @@ -14,9 +14,13 @@ on: type: boolean default: false os: - description: OS to run the job - required: true - type: string + description: OS to run the job + required: true + type: string + traceback_timestamps: + description: Set to us|1|ns|iso to enable printing timestamps on exceptions in tracebacks (for feature coverage) + required: false + type: string test-opts: description: Extra options to pass to the test runner via TESTOPTS required: false @@ -35,6 +39,7 @@ jobs: OPENSSL_VER: 3.5.5 PYTHONSTRICTEXTENSIONBUILD: 1 TERM: linux + PYTHON_TRACEBACK_TIMESTAMPS: ${{ inputs.traceback_timestamps }} steps: - uses: actions/checkout@v6 with: diff --git a/.github/workflows/reusable-windows.yml b/.github/workflows/reusable-windows.yml index 2f667ace9194d7..a637c542201d6b 100644 --- a/.github/workflows/reusable-windows.yml +++ b/.github/workflows/reusable-windows.yml @@ -25,6 +25,7 @@ jobs: timeout-minutes: 60 env: ARCH: ${{ inputs.arch }} + PYTHON_TRACEBACK_TIMESTAMPS: 'ns' steps: - uses: actions/checkout@v6 with: diff --git a/Doc/c-api/init_config.rst b/Doc/c-api/init_config.rst index f6dc604a609cb1..fdde06fd7b8766 100644 --- a/Doc/c-api/init_config.rst +++ b/Doc/c-api/init_config.rst @@ -493,6 +493,10 @@ Configuration Options - :c:member:`tracemalloc ` - ``int`` - Read-only + * - ``"traceback_timestamps"`` + - :c:member:`traceback_timestamps ` + - ``str`` + - Read-only * - ``"use_environment"`` - :c:member:`use_environment ` - ``bool`` @@ -1894,6 +1898,25 @@ PyConfig Default: ``-1`` in Python mode, ``0`` in isolated mode. + .. c:member:: wchar_t* traceback_timestamps + + Format of timestamps shown in tracebacks. + + If not ``NULL`` or an empty string, timestamps of exceptions are collected + and will be displayed in the configured format. Acceptable values are: + + * ``"us"``: Display timestamps in microseconds + * ``"ns"``: Display timestamps in nanoseconds + * ``"iso"``: Display timestamps in ISO-8601 format + * ``""``: Collection and display is disabled. + + Set by the :option:`-X traceback_timestamps=FORMAT <-X>` command line + option or the :envvar:`PYTHON_TRACEBACK_TIMESTAMPS` environment variable. + + Default: ``NULL`` (timestamps disabled). + + .. versionadded:: next + .. c:member:: int perf_profiling Enable the Linux ``perf`` profiler support? diff --git a/Doc/library/doctest.rst b/Doc/library/doctest.rst index 3298697af8511b..e1558c7bc84afe 100644 --- a/Doc/library/doctest.rst +++ b/Doc/library/doctest.rst @@ -539,6 +539,11 @@ Some details you should read once, but won't need to remember: everything following the leftmost colon and any module information in the exception name is ignored. +* When the :const:`IGNORE_EXCEPTION_TIMESTAMPS` doctest option is specified, + timestamps of the formats that :envvar:`PYTHON_TRACEBACK_TIMESTAMPS` + environment variable could append to exception messages are stripped from + tracebacks generated by the code under test before comparison. + * The interactive shell omits the traceback header line for some :exc:`SyntaxError`\ s. But doctest uses the traceback header line to distinguish exceptions from non-exceptions. So in the rare case where you need @@ -661,6 +666,22 @@ doctest decides whether actual output matches an example's expected output: to the module containing the exception under test. +.. data:: IGNORE_EXCEPTION_TIMESTAMPS + + When the :envvar:`PYTHON_TRACEBACK_TIMESTAMPS` environment variable is set, + exception and warning messages rendered in tracebacks may have a timestamp + value appended after the message. This strips all possible formats of that + timestamp tag that may be appended to an exception message in generated + tracebacks before comparing. + + :const:`ELLIPSIS` and :const:`IGNORE_EXCEPTION_DETAIL` could also be used to + avoid matching those. This can be cleaner when you need to test specific + details of exception messages. + + .. versionadded:: next + :const:`IGNORE_EXCEPTION_TIMESTAMPS` was added. + + .. data:: SKIP When specified, do not run the example at all. This can be useful in contexts diff --git a/Doc/library/exceptions.rst b/Doc/library/exceptions.rst index 7fc6055aa9a881..c81f8c46c8579a 100644 --- a/Doc/library/exceptions.rst +++ b/Doc/library/exceptions.rst @@ -159,6 +159,37 @@ The following exceptions are used mostly as base classes for other exceptions. .. versionadded:: 3.11 + .. attribute:: __timestamp_ns__ + + The absolute time in nanoseconds at which this exception was instantiated + (usually: when it was raised). + Having the same accuracy and time epoch as :func:`time.time_ns`. + Collection and display of these timestamps after the exception message in + tracebacks is off by default but can be configured using the + :envvar:`PYTHON_TRACEBACK_TIMESTAMPS` environment variable or the + :option:`-X traceback_timestamps <-X>` command line option. In + applications with complicated exception chains and exception groups it + may be useful to help understand what happened when. The value will be + ``0`` if a timestamp was not recorded. :exc:`StopIteration` and + :exc:`StopAsyncIteration` never record timestamps as those are primarily + for control flow. + + With ``PYTHON_TRACEBACK_TIMESTAMPS=iso`` in the environment :: + + Traceback (most recent call last): + File "", line 1, in + raise RuntimeError("example") + RuntimeError: example <@2025-02-08T01:21:28.675309Z> + + With ``PYTHON_TRACEBACK_TIMESTAMPS=ns`` in the environment :: + + Traceback (most recent call last): + File "", line 1, in + raise RuntimeError("example") + RuntimeError: example <@1739172733527638530ns> + + .. versionadded:: next + .. exception:: Exception diff --git a/Doc/library/sys.rst b/Doc/library/sys.rst index b1461b0cbaf528..64a7726ffebbfe 100644 --- a/Doc/library/sys.rst +++ b/Doc/library/sys.rst @@ -652,6 +652,11 @@ always available. Unless explicitly noted otherwise, all variables are read-only - :option:`-X context_aware_warnings <-X>` and :envvar:`PYTHON_CONTEXT_AWARE_WARNINGS` + * - .. attribute:: flags.traceback_timestamps + - :option:`-X traceback_timestamps <-X>` and + :envvar:`PYTHON_TRACEBACK_TIMESTAMPS`. This is a string containing + the selected format (``us``, ``ns``, ``iso``), or an empty string + when disabled. .. versionchanged:: 3.2 Added ``quiet`` attribute for the new :option:`-q` flag. @@ -688,6 +693,9 @@ always available. Unless explicitly noted otherwise, all variables are read-only .. versionchanged:: 3.14 Added the ``context_aware_warnings`` attribute. + .. versionchanged:: next + Added the ``traceback_timestamps`` attribute. + .. data:: float_info diff --git a/Doc/library/traceback.rst b/Doc/library/traceback.rst index b5464ac55ddfa9..84a80b7d560aa3 100644 --- a/Doc/library/traceback.rst +++ b/Doc/library/traceback.rst @@ -8,15 +8,14 @@ -------------- -This module provides a standard interface to extract, format and print -stack traces of Python programs. It is more flexible than the -interpreter's default traceback display, and therefore makes it -possible to configure certain aspects of the output. Finally, -it contains a utility for capturing enough information about an -exception to print it later, without the need to save a reference -to the actual exception. Since exceptions can be the roots of large -objects graph, this utility can significantly improve -memory management. +This module provides a standard interface to extract, format and print stack +traces of Python programs. While it has been around forever, it is used by +default for more flexible traceback display as of Python 3.13. It enables +configuring various aspects of the output. Finally, it contains utility classes +for capturing enough information about an exception to print it later, without +the need to save a reference to the actual exception. Since exceptions can be +the roots of large objects graph, that can significantly improve memory +management. .. index:: pair: object; traceback @@ -48,6 +47,10 @@ The module's API can be divided into two parts: Output is colorized by default and can be :ref:`controlled using environment variables `. +.. versionadded:: next + Tracebacks can now contain timestamps. Display of which can be configured by + the :envvar:`PYTHON_TRACEBACK_TIMESTAMPS` environment variable or the + :option:`-X traceback_timestamps <-X>` command line option. Module-Level Functions ---------------------- @@ -76,7 +79,7 @@ Module-Level Functions .. function:: print_exception(exc, /[, value, tb], limit=None, \ - file=None, chain=True) + file=None, chain=True, \*, no_timestamp=False) Print exception information and stack trace entries from :ref:`traceback object ` @@ -105,6 +108,12 @@ Module-Level Functions printed as well, like the interpreter itself does when printing an unhandled exception. + If *no_timestamp* is ``True`` and a traceback timestamp format is enabled via the + :envvar:`PYTHON_TRACEBACK_TIMESTAMPS` environment variable or the + :option:`-X traceback_timestamps <-X>` option, any timestamp after the exception + message will be omitted. This is useful for tests or other situations where + you need consistent output regardless of when exceptions occur. + .. versionchanged:: 3.5 The *etype* argument is ignored and inferred from the type of *value*. @@ -112,6 +121,9 @@ Module-Level Functions The *etype* parameter has been renamed to *exc* and is now positional-only. + .. versionchanged:: next + The *no_timestamp* keyword only argument was added. + .. function:: print_exc(limit=None, file=None, chain=True) @@ -178,7 +190,8 @@ Module-Level Functions text line is not ``None``. -.. function:: format_exception_only(exc, /[, value], *, show_group=False) +.. function:: format_exception_only(exc, /[, value], \*, show_group=False, \ + no_timestamp=False) Format the exception part of a traceback using an exception value such as given by :data:`sys.last_value`. The return value is a list of strings, each @@ -196,6 +209,12 @@ Module-Level Functions :exc:`BaseExceptionGroup`, the nested exceptions are included as well, recursively, with indentation relative to their nesting depth. + If *no_timestamp* is ``True`` and a traceback timestamp formatting is enabled + via the :envvar:`PYTHON_TRACEBACK_TIMESTAMPS` environment variable or the + :option:`-X traceback_timestamps <-X>` command line option, any timestamp + after the exception message will be omitted. This is useful for tests or + other situations where you need canonical output. + .. versionchanged:: 3.10 The *etype* parameter has been renamed to *exc* and is now positional-only. @@ -207,8 +226,12 @@ Module-Level Functions .. versionchanged:: 3.13 *show_group* parameter was added. + .. versionchanged:: next + The *no_timestamp* keyword only argument was added. + -.. function:: format_exception(exc, /[, value, tb], limit=None, chain=True) +.. function:: format_exception(exc, /[, value, tb], limit=None, chain=True, \ + \*, no_timestamp=False) Format a stack trace and the exception information. The arguments have the same meaning as the corresponding arguments to :func:`print_exception`. The @@ -216,6 +239,13 @@ Module-Level Functions containing internal newlines. When these lines are concatenated and printed, exactly the same text is printed as does :func:`print_exception`. + If *no_timestamp* is ``True`` and a traceback timestamp formatting is enabled + via the :envvar:`PYTHON_TRACEBACK_TIMESTAMPS` environment variable or the + :option:`-X traceback_timestamps <-X>` command line option, any timestamp + after the exception message will be omitted. This is useful for tests or + other situations where you need consistent output regardless of when + exceptions occur. + .. versionchanged:: 3.5 The *etype* argument is ignored and inferred from the type of *value*. @@ -223,6 +253,9 @@ Module-Level Functions This function's behavior and signature were modified to match :func:`print_exception`. + .. versionchanged:: next + The *no_timestamp* keyword only argument was added. + .. function:: format_exc(limit=None, chain=True) @@ -270,6 +303,19 @@ Module-Level Functions .. versionadded:: 3.5 +.. function:: strip_exc_timestamps(output) + + Given *output* of ``str`` or ``bytes`` presumed to contain a rendered + traceback, if traceback timestamps are enabled (see + :envvar:`PYTHON_TRACEBACK_TIMESTAMPS` or the :option:`-X traceback_timestamps <-X>` + option) returns output of the same type with all formatted exception message timestamp + values removed. When timestamps are disabled, returns *output* unchanged. + + This function is useful when you need to compare exception outputs or process + them without the timestamp information. + + .. versionadded:: next + :class:`!TracebackException` Objects ------------------------------------ @@ -283,7 +329,7 @@ storing this information by avoiding holding references to In addition, they expose more options to configure the output compared to the module-level functions described above. -.. class:: TracebackException(exc_type, exc_value, exc_traceback, *, limit=None, lookup_lines=True, capture_locals=False, compact=False, max_group_width=15, max_group_depth=10) +.. class:: TracebackException(exc_type, exc_value, exc_traceback, \*, limit=None, lookup_lines=True, capture_locals=False, compact=False, max_group_width=15, max_group_depth=10, no_timestamp=False) Capture an exception for later rendering. The meaning of *limit*, *lookup_lines* and *capture_locals* are as for the :class:`StackSummary` @@ -303,12 +349,19 @@ the module-level functions described above. group's exceptions array. The formatted output is truncated when either limit is exceeded. + If *no_timestamp* is ``True`` the ``__timestamp_ns__`` attribute from the + exception will not be rendered when formatting this + :class:`!TracebackException`. + .. versionchanged:: 3.10 Added the *compact* parameter. .. versionchanged:: 3.11 Added the *max_group_width* and *max_group_depth* parameters. + .. versionchanged:: next + Added the *no_timestamp* parameter. + .. attribute:: __cause__ A :class:`!TracebackException` of the original @@ -391,21 +444,21 @@ the module-level functions described above. For syntax errors - the compiler error message. - .. classmethod:: from_exception(exc, *, limit=None, lookup_lines=True, capture_locals=False) + .. classmethod:: from_exception(exc, \*, limit=None, lookup_lines=True, capture_locals=False) Capture an exception for later rendering. *limit*, *lookup_lines* and *capture_locals* are as for the :class:`StackSummary` class. Note that when locals are captured, they are also shown in the traceback. - .. method:: print(*, file=None, chain=True) + .. method:: print(\*, file=None, chain=True) Print to *file* (default ``sys.stderr``) the exception information returned by :meth:`format`. .. versionadded:: 3.11 - .. method:: format(*, chain=True) + .. method:: format(\*, chain=True) Format the exception. @@ -416,7 +469,7 @@ the module-level functions described above. some containing internal newlines. :func:`~traceback.print_exception` is a wrapper around this method which just prints the lines to a file. - .. method:: format_exception_only(*, show_group=False) + .. method:: format_exception_only(\*, show_group=False) Format the exception part of the traceback. @@ -449,7 +502,7 @@ the module-level functions described above. .. class:: StackSummary - .. classmethod:: extract(frame_gen, *, limit=None, lookup_lines=True, capture_locals=False) + .. classmethod:: extract(frame_gen, \*, limit=None, lookup_lines=True, capture_locals=False) Construct a :class:`!StackSummary` object from a frame generator (such as is returned by :func:`~traceback.walk_stack` or @@ -794,4 +847,3 @@ With the helper class, we have more options:: 1/0 ~^~ ZeroDivisionError: division by zero - diff --git a/Doc/using/cmdline.rst b/Doc/using/cmdline.rst index ce6872f3c0fda3..7fd6f52c4c5712 100644 --- a/Doc/using/cmdline.rst +++ b/Doc/using/cmdline.rst @@ -709,6 +709,15 @@ Miscellaneous options .. versionadded:: 3.15 + * :samp:`-X traceback_timestamps=[us|ns|iso|0|1]` enables or configures timestamp + display in exception tracebacks. When enabled, each exception's traceback + will include a timestamp showing when the exception occurred. The format + options are: ``us`` (microseconds), ``ns`` + (nanoseconds), ``iso`` (ISO-8601 formatted time), ``0`` (disable timestamps), + and ``1`` (equivalent to ``us``). See also :envvar:`PYTHON_TRACEBACK_TIMESTAMPS`. + + .. versionadded:: next + It also allows passing arbitrary values and retrieving them through the :data:`sys._xoptions` dictionary. @@ -1406,6 +1415,31 @@ conflict. .. versionadded:: 3.15 +.. envvar:: PYTHON_TRACEBACK_TIMESTAMPS + + If this variable is set to one of the following values, tracebacks printed + by the runtime will be annotated with the timestamp of each exception. The + values control the format of the timestamp: + + * ``us`` or ``1``: Prints decimal timestamps with microsecond precision. + * ``ns``: Prints the raw timestamp in nanoseconds. + * ``iso``: Prints the timestamp formatted by :meth:`~datetime.datetime.isoformat` (also microsecond precision). + * ``0``: Explicitly disables timestamps. + + When unset, timestamps are disabled by default. The time is not recorded on + the :exc:`StopIteration` family of exceptions for performance reasons as those + are used for control flow rather than errors. If set to empty or invalid values, + this feature remains disabled when using the environment variable. + + Note that the command line option :option:`-X` ``traceback_timestamps`` takes + precedence over this environment variable when both are specified. + + Formatting of the timestamps only happens at printing time. The ``iso`` + format may be slower due to the complexity of the code involved but is much + more readable. + + .. versionadded:: next + Debug-mode variables ~~~~~~~~~~~~~~~~~~~~ diff --git a/Include/cpython/initconfig.h b/Include/cpython/initconfig.h index 1ccc496c63ac78..824f5265754b7c 100644 --- a/Include/cpython/initconfig.h +++ b/Include/cpython/initconfig.h @@ -150,6 +150,7 @@ typedef struct PyConfig { wchar_t *dump_refs_file; int malloc_stats; int pymalloc_hugepages; + wchar_t *traceback_timestamps; wchar_t *filesystem_encoding; wchar_t *filesystem_errors; wchar_t *pycache_prefix; diff --git a/Include/cpython/pyerrors.h b/Include/cpython/pyerrors.h index be2e3b641c25cb..24cb35f12d1c67 100644 --- a/Include/cpython/pyerrors.h +++ b/Include/cpython/pyerrors.h @@ -2,12 +2,15 @@ # error "this header file must not be included directly" #endif +#include "cpython/pytime.h" /* for PyTime_t */ + /* Error objects */ /* PyException_HEAD defines the initial segment of every exception class. */ #define PyException_HEAD PyObject_HEAD PyObject *dict;\ PyObject *args; PyObject *notes; PyObject *traceback;\ PyObject *context; PyObject *cause;\ + PyTime_t timestamp_ns;\ char suppress_context; typedef struct { diff --git a/Include/internal/pycore_global_objects_fini_generated.h b/Include/internal/pycore_global_objects_fini_generated.h index 64e3438f9157fe..e788ed6148ad9d 100644 --- a/Include/internal/pycore_global_objects_fini_generated.h +++ b/Include/internal/pycore_global_objects_fini_generated.h @@ -1516,6 +1516,7 @@ _PyStaticObjects_CheckRefcnt(PyInterpreterState *interp) { _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(__sub__)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(__subclasscheck__)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(__subclasshook__)); + _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(__timestamp_ns__)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(__truediv__)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(__trunc__)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(__type_params__)); @@ -1559,6 +1560,7 @@ _PyStaticObjects_CheckRefcnt(PyInterpreterState *interp) { _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_loop)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_needs_com_addref_)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_only_immortal)); + _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_print_exception_bltin)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_restype_)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_showwarnmsg)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_shutdown)); @@ -1567,6 +1569,7 @@ _PyStaticObjects_CheckRefcnt(PyInterpreterState *interp) { _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_strptime_datetime_date)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_strptime_datetime_datetime)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_strptime_datetime_time)); + _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_timestamp_formatter)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_type_)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_uninitialized_submodules)); _PyStaticObject_CheckRefcnt((PyObject *)&_Py_ID(_warn_unawaited_coroutine)); diff --git a/Include/internal/pycore_global_strings.h b/Include/internal/pycore_global_strings.h index 78ed30dd7f62a2..877cce07ef4d9e 100644 --- a/Include/internal/pycore_global_strings.h +++ b/Include/internal/pycore_global_strings.h @@ -239,6 +239,7 @@ struct _Py_global_strings { STRUCT_FOR_ID(__sub__) STRUCT_FOR_ID(__subclasscheck__) STRUCT_FOR_ID(__subclasshook__) + STRUCT_FOR_ID(__timestamp_ns__) STRUCT_FOR_ID(__truediv__) STRUCT_FOR_ID(__trunc__) STRUCT_FOR_ID(__type_params__) @@ -282,6 +283,7 @@ struct _Py_global_strings { STRUCT_FOR_ID(_loop) STRUCT_FOR_ID(_needs_com_addref_) STRUCT_FOR_ID(_only_immortal) + STRUCT_FOR_ID(_print_exception_bltin) STRUCT_FOR_ID(_restype_) STRUCT_FOR_ID(_showwarnmsg) STRUCT_FOR_ID(_shutdown) @@ -290,6 +292,7 @@ struct _Py_global_strings { STRUCT_FOR_ID(_strptime_datetime_date) STRUCT_FOR_ID(_strptime_datetime_datetime) STRUCT_FOR_ID(_strptime_datetime_time) + STRUCT_FOR_ID(_timestamp_formatter) STRUCT_FOR_ID(_type_) STRUCT_FOR_ID(_uninitialized_submodules) STRUCT_FOR_ID(_warn_unawaited_coroutine) diff --git a/Include/internal/pycore_runtime_init_generated.h b/Include/internal/pycore_runtime_init_generated.h index d4b7b090f93f31..a525c040d74eed 100644 --- a/Include/internal/pycore_runtime_init_generated.h +++ b/Include/internal/pycore_runtime_init_generated.h @@ -1514,6 +1514,7 @@ extern "C" { INIT_ID(__sub__), \ INIT_ID(__subclasscheck__), \ INIT_ID(__subclasshook__), \ + INIT_ID(__timestamp_ns__), \ INIT_ID(__truediv__), \ INIT_ID(__trunc__), \ INIT_ID(__type_params__), \ @@ -1557,6 +1558,7 @@ extern "C" { INIT_ID(_loop), \ INIT_ID(_needs_com_addref_), \ INIT_ID(_only_immortal), \ + INIT_ID(_print_exception_bltin), \ INIT_ID(_restype_), \ INIT_ID(_showwarnmsg), \ INIT_ID(_shutdown), \ @@ -1565,6 +1567,7 @@ extern "C" { INIT_ID(_strptime_datetime_date), \ INIT_ID(_strptime_datetime_datetime), \ INIT_ID(_strptime_datetime_time), \ + INIT_ID(_timestamp_formatter), \ INIT_ID(_type_), \ INIT_ID(_uninitialized_submodules), \ INIT_ID(_warn_unawaited_coroutine), \ diff --git a/Include/internal/pycore_unicodeobject_generated.h b/Include/internal/pycore_unicodeobject_generated.h index d843674f180902..3bbf2588b47519 100644 --- a/Include/internal/pycore_unicodeobject_generated.h +++ b/Include/internal/pycore_unicodeobject_generated.h @@ -736,6 +736,10 @@ _PyUnicode_InitStaticStrings(PyInterpreterState *interp) { _PyUnicode_InternStatic(interp, &string); assert(_PyUnicode_CheckConsistency(string, 1)); assert(PyUnicode_GET_LENGTH(string) != 1); + string = &_Py_ID(__timestamp_ns__); + _PyUnicode_InternStatic(interp, &string); + assert(_PyUnicode_CheckConsistency(string, 1)); + assert(PyUnicode_GET_LENGTH(string) != 1); string = &_Py_ID(__truediv__); _PyUnicode_InternStatic(interp, &string); assert(_PyUnicode_CheckConsistency(string, 1)); @@ -908,6 +912,10 @@ _PyUnicode_InitStaticStrings(PyInterpreterState *interp) { _PyUnicode_InternStatic(interp, &string); assert(_PyUnicode_CheckConsistency(string, 1)); assert(PyUnicode_GET_LENGTH(string) != 1); + string = &_Py_ID(_print_exception_bltin); + _PyUnicode_InternStatic(interp, &string); + assert(_PyUnicode_CheckConsistency(string, 1)); + assert(PyUnicode_GET_LENGTH(string) != 1); string = &_Py_ID(_restype_); _PyUnicode_InternStatic(interp, &string); assert(_PyUnicode_CheckConsistency(string, 1)); @@ -940,6 +948,10 @@ _PyUnicode_InitStaticStrings(PyInterpreterState *interp) { _PyUnicode_InternStatic(interp, &string); assert(_PyUnicode_CheckConsistency(string, 1)); assert(PyUnicode_GET_LENGTH(string) != 1); + string = &_Py_ID(_timestamp_formatter); + _PyUnicode_InternStatic(interp, &string); + assert(_PyUnicode_CheckConsistency(string, 1)); + assert(PyUnicode_GET_LENGTH(string) != 1); string = &_Py_ID(_type_); _PyUnicode_InternStatic(interp, &string); assert(_PyUnicode_CheckConsistency(string, 1)); diff --git a/Lib/doctest.py b/Lib/doctest.py index 0fcfa1e3e97144..40b86d55dca283 100644 --- a/Lib/doctest.py +++ b/Lib/doctest.py @@ -56,6 +56,7 @@ def _test(): 'ELLIPSIS', 'SKIP', 'IGNORE_EXCEPTION_DETAIL', + 'IGNORE_EXCEPTION_TIMESTAMPS', 'COMPARISON_FLAGS', 'REPORT_UDIFF', 'REPORT_CDIFF', @@ -159,13 +160,15 @@ def register_optionflag(name): ELLIPSIS = register_optionflag('ELLIPSIS') SKIP = register_optionflag('SKIP') IGNORE_EXCEPTION_DETAIL = register_optionflag('IGNORE_EXCEPTION_DETAIL') +IGNORE_EXCEPTION_TIMESTAMPS = register_optionflag('IGNORE_EXCEPTION_TIMESTAMPS') COMPARISON_FLAGS = (DONT_ACCEPT_TRUE_FOR_1 | DONT_ACCEPT_BLANKLINE | NORMALIZE_WHITESPACE | ELLIPSIS | SKIP | - IGNORE_EXCEPTION_DETAIL) + IGNORE_EXCEPTION_DETAIL | + IGNORE_EXCEPTION_TIMESTAMPS) REPORT_UDIFF = register_optionflag('REPORT_UDIFF') REPORT_CDIFF = register_optionflag('REPORT_CDIFF') @@ -270,7 +273,7 @@ def _exception_traceback(exc_info): # Get a traceback message. excout = StringIO() exc_type, exc_val, exc_tb = exc_info - traceback.print_exception(exc_type, exc_val, exc_tb, file=excout) + traceback.print_exception(exc_type, exc_val, exc_tb, file=excout, no_timestamp=True) return excout.getvalue() # Override some StringIO methods. @@ -1446,7 +1449,7 @@ def __run(self, test, compileflags, out): # The example raised an exception: check if it was expected. else: - formatted_ex = traceback.format_exception_only(*exc_info[:2]) + formatted_ex = traceback.format_exception_only(*exc_info[:2], no_timestamp=True) if issubclass(exc_info[0], SyntaxError): # SyntaxError / IndentationError is special: # we don't care about the carets / suggestions / etc @@ -1781,6 +1784,15 @@ def check_output(self, want, got, optionflags): if got == want: return True + # This flag removes everything that looks like a timestamp as can + # be configured to display after exception messages in tracebacks. + # We're assuming nobody will ever write these in their 'want' docs + # as the feature is off by default, intended for production use. + if optionflags & IGNORE_EXCEPTION_TIMESTAMPS: + got = traceback.strip_exc_timestamps(got) + if got == want: + return True + # The ELLIPSIS flag says to let the sequence "..." in `want` # match any substring in `got`. if optionflags & ELLIPSIS: diff --git a/Lib/idlelib/idle_test/test_grep.py b/Lib/idlelib/idle_test/test_grep.py index d67dba76911fcf..ee70aa8bf5c933 100644 --- a/Lib/idlelib/idle_test/test_grep.py +++ b/Lib/idlelib/idle_test/test_grep.py @@ -10,6 +10,7 @@ from test.support import captured_stdout from idlelib.idle_test.mock_tk import Var import os +from pprint import pformat import re @@ -139,7 +140,7 @@ def test_found(self): pat = '""" !Changing this line will break Test_findfile.test_found!' lines = self.report(pat) - self.assertEqual(len(lines), 5) + self.assertEqual(len(lines), 5, msg=f"{pformat(lines)}") self.assertIn(pat, lines[0]) self.assertIn('py: 1:', lines[1]) # line number 1 self.assertIn('2', lines[3]) # hits found 2 diff --git a/Lib/idlelib/idle_test/test_run.py b/Lib/idlelib/idle_test/test_run.py index 9a9d3b7b4e219c..4cabf8d29f2644 100644 --- a/Lib/idlelib/idle_test/test_run.py +++ b/Lib/idlelib/idle_test/test_run.py @@ -9,6 +9,7 @@ import idlelib from idlelib.idle_test.mock_idle import Func from test.support import force_not_colorized +import traceback idlelib.testing = True # Use {} for executing test user code. @@ -56,6 +57,7 @@ def test_get_message(self): except exc: typ, val, tb = sys.exc_info() actual = run.get_message_lines(typ, val, tb)[0] + actual = traceback.strip_exc_timestamps(actual) expect = f'{exc.__name__}: {msg}' self.assertEqual(actual, expect) @@ -77,6 +79,7 @@ def test_get_multiple_message(self, mock): with captured_stderr() as output: run.print_exception() actual = output.getvalue() + actual = traceback.strip_exc_timestamps(actual) self.assertIn(msg1, actual) self.assertIn(msg2, actual) subtests += 1 diff --git a/Lib/subprocess.py b/Lib/subprocess.py index b943fba3d33f4b..192f4a27bb09a6 100644 --- a/Lib/subprocess.py +++ b/Lib/subprocess.py @@ -351,8 +351,16 @@ def _args_from_interpreter_flags(): # -X options if dev_mode: args.extend(('-X', 'dev')) - for opt in ('faulthandler', 'tracemalloc', 'importtime', - 'frozen_modules', 'showrefcount', 'utf8', 'gil'): + for opt in ( + 'faulthandler', + 'frozen_modules', + 'gil', + 'importtime', + 'showrefcount', + 'traceback_timestamps', + 'tracemalloc', + 'utf8', + ): if opt in xoptions: value = xoptions[opt] if value is True: diff --git a/Lib/test/support/__init__.py b/Lib/test/support/__init__.py index 3da662b0c4d50a..0ce0df47a635da 100644 --- a/Lib/test/support/__init__.py +++ b/Lib/test/support/__init__.py @@ -12,6 +12,7 @@ import os import re import stat +import struct import sys import sysconfig import textwrap @@ -1026,16 +1027,28 @@ def expected_failure_if_gil_disabled(): _header = 'PHBBInP' else: _header = 'nP' -_align = '0n' _vheader = _header + 'n' +def _align(fmt): + """Pad the struct the way a C compiler does. + + C alignment pads the struct total size so that arrays keep the largest + alignment element aligned in an array. + """ + align = '0n' + if 'q' in fmt or 'Q' in fmt: + align = '0q' + if 'd' in fmt: + align = '0d' + return align + def calcobjsize(fmt): - import struct - return struct.calcsize(_header + fmt + _align) + whole_fmt = _header + fmt + return struct.calcsize(whole_fmt + _align(whole_fmt)) def calcvobjsize(fmt): - import struct - return struct.calcsize(_vheader + fmt + _align) + whole_fmt = _vheader + fmt + return struct.calcsize(whole_fmt + _align(whole_fmt)) _TPFLAGS_STATIC_BUILTIN = 1<<1 @@ -3018,6 +3031,49 @@ def is_slot_wrapper(name, value): yield name, True +@contextlib.contextmanager +def no_traceback_timestamps(): + import traceback + from .os_helper import EnvironmentVarGuard + + with ( + swap_attr(traceback, "_TIMESTAMP_FORMAT", ""), + EnvironmentVarGuard() as env, + ): + # This prevents it from being on in child processes. + env.unset("PYTHON_TRACEBACK_TIMESTAMPS") + # Silence our other-path pythonrun.c print_exception_message(). + tf = getattr(traceback, "_timestamp_formatter", "Nope!") + if tf != "Nope!": + del traceback._timestamp_formatter + yield + if tf != "Nope!": + traceback._timestamp_formatter = tf + + +def force_no_traceback_timestamps(func): + """Callable decorator: Force timestamps on tracebacks to be off.""" + @functools.wraps(func) + def wrapper(*args, **kwargs): + with no_traceback_timestamps(): + return func(*args, **kwargs) + return wrapper + + +def force_no_traceback_timestamps_test_class(cls): + """Class decorator: Force timestamps off for the entire test class.""" + original_setUpClass = cls.setUpClass + + @classmethod + @functools.wraps(cls.setUpClass) + def new_setUpClass(cls): + cls.enterClassContext(no_traceback_timestamps()) + original_setUpClass() + + cls.setUpClass = new_setUpClass + return cls + + @contextlib.contextmanager def force_color(color: bool): import _colorize diff --git a/Lib/test/test_capi/test_config.py b/Lib/test/test_capi/test_config.py index f10ad50d3bea7e..35292ab9bdd85b 100644 --- a/Lib/test/test_capi/test_config.py +++ b/Lib/test/test_capi/test_config.py @@ -88,6 +88,7 @@ def test_config_get(self): ("stdio_encoding", str, None), ("stdio_errors", str, None), ("stdlib_dir", str | None, "_stdlib_dir"), + ("traceback_timestamps", str, None), ("tracemalloc", int, None), ("use_environment", bool, None), ("use_frozen_modules", bool, None), @@ -174,6 +175,7 @@ def test_config_get_sys_flags(self): ("warn_default_encoding", "warn_default_encoding", False), ("safe_path", "safe_path", False), ("int_max_str_digits", "int_max_str_digits", False), + ("traceback_timestamps", "traceback_timestamps", False), # "gil", "thread_inherit_context" and "context_aware_warnings" are tested below ): with self.subTest(flag=flag, name=name, negate=negate): diff --git a/Lib/test/test_cmd_line.py b/Lib/test/test_cmd_line.py index 5f035c35367d64..9c66c02fe8cfd3 100644 --- a/Lib/test/test_cmd_line.py +++ b/Lib/test/test_cmd_line.py @@ -73,8 +73,9 @@ def test_help_env(self): def test_help_xoptions(self): out = self.verify_valid_flag('--help-xoptions') self.assertIn(b'-X dev', out) + sort_key = lambda k: k.replace(b'_', b'').replace(b'-', b'').lower() options = re.findall(rb'^-X (\w+)', out, re.MULTILINE) - self.assertEqual(options, sorted(options), + self.assertEqual(options, sorted(options, key=sort_key), "options should be sorted alphabetically") @support.cpython_only diff --git a/Lib/test/test_cmd_line_script.py b/Lib/test/test_cmd_line_script.py index 73b1f671c58555..e2846144869462 100644 --- a/Lib/test/test_cmd_line_script.py +++ b/Lib/test/test_cmd_line_script.py @@ -10,6 +10,7 @@ import os.path import py_compile import subprocess +import traceback import io import textwrap @@ -693,6 +694,7 @@ def test_source_lines_are_shown_when_running_source(self): b' 1/0', b' ~^~', b'ZeroDivisionError: division by zero'] + stderr = traceback.strip_exc_timestamps(stderr) self.assertEqual(stderr.splitlines(), expected_lines) def test_syntaxerror_does_not_crash(self): diff --git a/Lib/test/test_code_module.py b/Lib/test/test_code_module.py index 3642b47c2c1f03..5b2c865046bbe5 100644 --- a/Lib/test/test_code_module.py +++ b/Lib/test/test_code_module.py @@ -157,7 +157,9 @@ def test_sysexcepthook(self): self.assertIs(type(self.sysmod.last_value), ValueError) self.assertIs(self.sysmod.last_traceback, self.sysmod.last_value.__traceback__) self.assertIs(self.sysmod.last_exc, self.sysmod.last_value) - self.assertEqual(traceback.format_exception(self.sysmod.last_exc), [ + self.assertEqual( + traceback.format_exception(self.sysmod.last_exc, no_timestamp=True), + [ 'Traceback (most recent call last):\n', ' File "", line 1, in \n', ' File "", line 2, in f\n', @@ -180,7 +182,9 @@ def test_sysexcepthook_syntax_error(self): self.assertIsNone(self.sysmod.last_traceback) self.assertIsNone(self.sysmod.last_value.__traceback__) self.assertIs(self.sysmod.last_exc, self.sysmod.last_value) - self.assertEqual(traceback.format_exception(self.sysmod.last_exc), [ + self.assertEqual( + traceback.format_exception(self.sysmod.last_exc, no_timestamp=True), + [ ' File "", line 2\n', ' x = ?\n', ' ^\n', @@ -200,7 +204,9 @@ def test_sysexcepthook_indentation_error(self): self.assertIsNone(self.sysmod.last_traceback) self.assertIsNone(self.sysmod.last_value.__traceback__) self.assertIs(self.sysmod.last_exc, self.sysmod.last_value) - self.assertEqual(traceback.format_exception(self.sysmod.last_exc), [ + self.assertEqual( + traceback.format_exception(self.sysmod.last_exc, no_timestamp=True), + [ ' File "", line 1\n', ' 1\n', 'IndentationError: unexpected indent\n']) @@ -285,6 +291,7 @@ def test_cause_tb(self): EOFError('Finished')] self.console.interact() output = ''.join(''.join(call[1]) for call in self.stderr.method_calls) + output = traceback.strip_exc_timestamps(output) expected = dedent(""" AttributeError @@ -306,6 +313,7 @@ def test_context_tb(self): EOFError('Finished')] self.console.interact() output = ''.join(''.join(call[1]) for call in self.stderr.method_calls) + output = traceback.strip_exc_timestamps(output) expected = dedent(""" Traceback (most recent call last): File "", line 1, in diff --git a/Lib/test/test_doctest/test_doctest.py b/Lib/test/test_doctest/test_doctest.py index b125693ab0891c..2f4a1b4e03cef7 100644 --- a/Lib/test/test_doctest/test_doctest.py +++ b/Lib/test/test_doctest/test_doctest.py @@ -201,10 +201,11 @@ def test_Example(): r""" >>> exc_msg = 'IndexError: pop from an empty list' >>> example = doctest.Example('[].pop()', '', exc_msg, ... lineno=5, indent=4, - ... options={doctest.ELLIPSIS: True}) + ... options={ + ... doctest.IGNORE_EXCEPTION_TIMESTAMPS: True}) >>> (example.source, example.want, example.exc_msg, ... example.lineno, example.indent, example.options) - ('[].pop()\n', '', 'IndexError: pop from an empty list\n', 5, 4, {8: True}) + ('[].pop()\n', '', 'IndexError: pop from an empty list\n', 5, 4, {64: True}) The constructor normalizes the `source` string to end in a newline: @@ -2325,7 +2326,7 @@ def test_pdb_set_trace_nested(): ... runner.run(test) ... finally: ... sys.stdin = real_stdin - ... # doctest: +REPORT_NDIFF + ... # doctest: +REPORT_NDIFF +IGNORE_EXCEPTION_TIMESTAMPS > (4)calls_set_trace() -> import pdb; pdb.set_trace() (Pdb) step @@ -2961,7 +2962,7 @@ def test_unittest_reportflags(): *NOTE*: These doctest are intentionally not placed in raw string to depict the trailing whitespace using `\x20` in the diff below. - >>> print(result.failures[0][1]) # doctest: +ELLIPSIS + >>> print(result.failures[0][1]) # doctest: +ELLIPSIS +IGNORE_EXCEPTION_TIMESTAMPS Traceback ... File ... >...>> if 1: diff --git a/Lib/test/test_embed.py b/Lib/test/test_embed.py index 45d0d8308dbdea..bc210771686b2d 100644 --- a/Lib/test/test_embed.py +++ b/Lib/test/test_embed.py @@ -633,6 +633,7 @@ class InitConfigTests(EmbeddingTestsMixin, unittest.TestCase): 'cpu_count': -1, 'faulthandler': False, 'tracemalloc': 0, + 'traceback_timestamps': "", 'perf_profiling': 0, 'import_time': 0, 'lazy_imports': -1, diff --git a/Lib/test/test_exceptions.py b/Lib/test/test_exceptions.py index 7354f8281d9682..1c9d0a0c2f18e0 100644 --- a/Lib/test/test_exceptions.py +++ b/Lib/test/test_exceptions.py @@ -15,7 +15,8 @@ cpython_only, gc_collect, no_tracing, script_helper, SuppressCrashReport, - force_not_colorized) + force_not_colorized, + force_no_traceback_timestamps) from test.support.import_helper import import_module from test.support.os_helper import TESTFN, unlink from test.support.warnings_helper import check_warnings @@ -2184,6 +2185,7 @@ def tearDown(self): unlink(TESTFN) @force_not_colorized + @force_no_traceback_timestamps def test_assertion_error_location(self): cases = [ ('assert None', @@ -2282,6 +2284,7 @@ def test_assertion_error_location(self): self.assertEqual(result[-3:], expected) @force_not_colorized + @force_no_traceback_timestamps def test_multiline_not_highlighted(self): cases = [ (""" diff --git a/Lib/test/test_import/__init__.py b/Lib/test/test_import/__init__.py index 437ab7031356b1..58e65236587279 100644 --- a/Lib/test/test_import/__init__.py +++ b/Lib/test/test_import/__init__.py @@ -23,6 +23,7 @@ import textwrap import threading import time +import traceback import types import warnings import unittest @@ -1004,7 +1005,9 @@ def test_script_shadowing_third_party(self): expected_error = error + ( rb" \(consider renaming '.*numpy.py' if it has the " - rb"same name as a library you intended to import\)\s+\z" + rb"same name as a library you intended to import\)" + + traceback.TIMESTAMP_AFTER_EXC_MSG_RE_GROUP.encode() + + rb"?\s+\Z" ) popen = script_helper.spawn_python(os.path.join(tmp, "numpy.py")) @@ -1025,14 +1028,18 @@ def test_script_maybe_not_shadowing_third_party(self): f.write("this_script_does_not_attempt_to_import_numpy = True") expected_error = ( - rb"AttributeError: module 'numpy' has no attribute 'attr'\s+\z" + rb"AttributeError: module 'numpy' has no attribute 'attr'" + + traceback.TIMESTAMP_AFTER_EXC_MSG_RE_GROUP.encode() + + rb"?\s+\Z" ) popen = script_helper.spawn_python('-c', 'import numpy; numpy.attr', cwd=tmp) stdout, stderr = popen.communicate() self.assertRegex(stdout, expected_error) expected_error = ( - rb"ImportError: cannot import name 'attr' from 'numpy' \(.*\)\s+\z" + rb"ImportError: cannot import name 'attr' from 'numpy' \(.*\)" + + traceback.TIMESTAMP_AFTER_EXC_MSG_RE_GROUP.encode() + + rb"?\s+\Z" ) popen = script_helper.spawn_python('-c', 'from numpy import attr', cwd=tmp) stdout, stderr = popen.communicate() diff --git a/Lib/test/test_interpreters/utils.py b/Lib/test/test_interpreters/utils.py index ae09aa457b48c7..9a12298ff53f48 100644 --- a/Lib/test/test_interpreters/utils.py +++ b/Lib/test/test_interpreters/utils.py @@ -10,6 +10,7 @@ import tempfile from textwrap import dedent import threading +import traceback import types import unittest @@ -457,8 +458,10 @@ def make_module(self, name, pathentry=None, text=None): @support.requires_subprocess() def run_python(self, *argv): + # Make assertions of specific traceback output simpler. + arguments = ["-X", "traceback_timestamps=0", *argv] proc = subprocess.run( - [sys.executable, *argv], + [sys.executable, *arguments], capture_output=True, text=True, ) @@ -472,6 +475,7 @@ def assert_python_ok(self, *argv): def assert_python_failure(self, *argv): exitcode, stdout, stderr = self.run_python(*argv) self.assertNotEqual(exitcode, 0) + stderr = traceback.strip_exc_timestamps(stderr) return stdout, stderr def assert_ns_equal(self, ns1, ns2, msg=None): diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 05dcea6ce0e98a..c93ad216d073df 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -55,6 +55,7 @@ from test.support.logging_helper import TestHandler import textwrap import threading +import traceback import asyncio import time import unittest @@ -827,7 +828,8 @@ def test_error_handling(self): with support.captured_stderr() as stderr: h.handle(r) msg = '\nRuntimeError: deliberate mistake\n' - self.assertIn(msg, stderr.getvalue()) + stderr = traceback.strip_exc_timestamps(stderr.getvalue()) + self.assertIn(msg, stderr) logging.raiseExceptions = False with support.captured_stderr() as stderr: @@ -4955,7 +4957,7 @@ def test_formatting(self): r = h.records[0] self.assertStartsWith(r.exc_text, 'Traceback (most recent call last):\n') - self.assertEndsWith(r.exc_text, + self.assertEndsWith(traceback.strip_exc_timestamps(r.exc_text), '\nRuntimeError: deliberate mistake') self.assertStartsWith(r.stack_info, 'Stack (most recent call last):\n') diff --git a/Lib/test/test_pdb.py b/Lib/test/test_pdb.py index 0e23cd6604379c..230e0337b6cc2a 100644 --- a/Lib/test/test_pdb.py +++ b/Lib/test/test_pdb.py @@ -667,7 +667,7 @@ def test_pdb_pp_repr_exc(): >>> def test_function(): ... import pdb; pdb.Pdb(nosigint=True, readrc=False).set_trace() - >>> with PdbTestInput([ # doctest: +NORMALIZE_WHITESPACE + >>> with PdbTestInput([ # doctest: +NORMALIZE_WHITESPACE +IGNORE_EXCEPTION_TIMESTAMPS ... 'p obj', ... 'pp obj', ... 'continue', @@ -871,7 +871,7 @@ def test_pdb_display_command(): ... a = 3 ... a = 4 - >>> with PdbTestInput([ # doctest: +ELLIPSIS + >>> with PdbTestInput([ # doctest: +ELLIPSIS +IGNORE_EXCEPTION_TIMESTAMPS ... 's', ... 'display +', ... 'display', @@ -1189,7 +1189,7 @@ def test_convenience_variables(): >>> def test_function(): ... util_function() - >>> with PdbTestInput([ # doctest: +ELLIPSIS, +NORMALIZE_WHITESPACE + >>> with PdbTestInput([ # doctest: +ELLIPSIS, +NORMALIZE_WHITESPACE +IGNORE_EXCEPTION_TIMESTAMPS ... 'step', # Step to try statement ... '$_frame.f_lineno', # Check frame convenience variable ... '$ _frame', # This should be a syntax error @@ -1688,7 +1688,7 @@ def test_post_mortem(): ... test_function_2() ... print('Not reached.') - >>> with PdbTestInput([ # doctest: +ELLIPSIS, +NORMALIZE_WHITESPACE + >>> with PdbTestInput([ # doctest: +ELLIPSIS +NORMALIZE_WHITESPACE +IGNORE_EXCEPTION_TIMESTAMPS ... 'step', # step to test_function_2() line ... 'next', # step over exception-raising call ... 'bt', # get a backtrace @@ -2200,7 +2200,7 @@ def test_pdb_await_support(): > (4)main() -> await pdb.Pdb(nosigint=True, readrc=False).set_trace_async() (Pdb) await non_exist() - *** NameError: name 'non_exist' is not defined + *** NameError: name 'non_exist' is not defined... > (4)main() -> await pdb.Pdb(nosigint=True, readrc=False).set_trace_async() (Pdb) s @@ -2806,7 +2806,7 @@ def test_pdb_closure(): ... g = 3 ... import pdb; pdb.Pdb(nosigint=True, readrc=False).set_trace() - >>> with PdbTestInput([ # doctest: +NORMALIZE_WHITESPACE + >>> with PdbTestInput([ # doctest: +NORMALIZE_WHITESPACE +IGNORE_EXCEPTION_TIMESTAMPS ... 'k', ... 'g', ... 'y = y', @@ -3120,7 +3120,7 @@ def test_pdb_issue_gh_101673(): ... a = 1 ... import pdb; pdb.Pdb(nosigint=True, readrc=False).set_trace() - >>> with PdbTestInput([ # doctest: +NORMALIZE_WHITESPACE + >>> with PdbTestInput([ # doctest: +NORMALIZE_WHITESPACE +IGNORE_EXCEPTION_TIMESTAMPS ... '!a = 2', ... 'll', ... 'p a', @@ -3443,7 +3443,7 @@ def test_pdb_issue_gh_65052(): >>> def test_function(): ... A() - >>> with PdbTestInput([ # doctest: +ELLIPSIS +NORMALIZE_WHITESPACE + >>> with PdbTestInput([ # doctest: +ELLIPSIS +NORMALIZE_WHITESPACE +IGNORE_EXCEPTION_TIMESTAMPS ... 's', ... 's', ... 'retval', @@ -4453,7 +4453,11 @@ def test_errors_in_command(self): 'debug doesnotexist', 'c', ]) - stdout, _ = self.run_pdb_script('pass', commands + '\n') + stdout, _ = self.run_pdb_script( + 'pass', + commands + '\n', + extra_env={'PYTHON_TRACEBACK_TIMESTAMPS':'0'}, + ) self.assertEqual(stdout.splitlines()[1:], [ '-> pass', diff --git a/Lib/test/test_remote_pdb.py b/Lib/test/test_remote_pdb.py index d26d63faa61ddb..62c673eef39b5a 100644 --- a/Lib/test/test_remote_pdb.py +++ b/Lib/test/test_remote_pdb.py @@ -8,6 +8,7 @@ import subprocess import sys import textwrap +import traceback import unittest import unittest.mock from contextlib import closing, contextmanager, redirect_stdout, redirect_stderr, ExitStack @@ -203,9 +204,9 @@ def sigint_stdout_write(s): self.assertEqual(actual_outgoing, expected_outgoing) self.assertEqual(completions, expected_completions) if expected_stdout_substring and not expected_stdout: - self.assertIn(expected_stdout_substring, stdout.getvalue()) + self.assertIn(expected_stdout_substring, traceback.strip_exc_timestamps(stdout.getvalue())) else: - self.assertEqual(stdout.getvalue(), expected_stdout) + self.assertEqual(traceback.strip_exc_timestamps(stdout.getvalue()), expected_stdout) input_mock.assert_has_calls([unittest.mock.call(p) for p in prompts]) actual_state = {k: getattr(client, k) for k in expected_state} self.assertEqual(actual_state, expected_state) diff --git a/Lib/test/test_repl.py b/Lib/test/test_repl.py index 27cd125078ea69..6372d5cf2a42a7 100644 --- a/Lib/test/test_repl.py +++ b/Lib/test/test_repl.py @@ -17,6 +17,7 @@ ) from test.support.script_helper import kill_python from test.support.import_helper import import_module +import traceback try: import pty @@ -181,10 +182,11 @@ def test_interactive_traceback_reporting(self): output = kill_python(p) self.assertEqual(p.returncode, 0) + output = traceback.strip_exc_timestamps(output) traceback_lines = output.splitlines()[-6:-1] expected_lines = [ "Traceback (most recent call last):", - " File \"\", line 1, in ", + ' File "", line 1, in ', " 1 / 0 / 3 / 4", " ~~^~~", "ZeroDivisionError: division by zero", @@ -204,6 +206,7 @@ def foo(x): output = kill_python(p) self.assertEqual(p.returncode, 0) + output = traceback.strip_exc_timestamps(output) traceback_lines = output.splitlines()[-8:-1] expected_lines = [ ' File "", line 1, in ', @@ -242,6 +245,7 @@ def make_repl(env): p = make_repl(env) p.stdin.write("1/0") output = kill_python(p) + output = traceback.strip_exc_timestamps(output) expected = dedent(""" Traceback (most recent call last): File "", line 1, in @@ -264,6 +268,7 @@ def make_repl(env): p = make_repl(env) p.stdin.write('foo()') output = kill_python(p) + output = traceback.strip_exc_timestamps(output) expected = dedent(""" Traceback (most recent call last): File "", line 1, in diff --git a/Lib/test/test_runpy.py b/Lib/test/test_runpy.py index 9f3bc8973eb8ac..3e15e400e07108 100644 --- a/Lib/test/test_runpy.py +++ b/Lib/test/test_runpy.py @@ -10,6 +10,7 @@ import sys import tempfile import textwrap +import traceback import unittest import warnings from test.support import ( @@ -838,7 +839,8 @@ def assertSigInt(self, cmd, *args, **kwargs): # Use -E to ignore PYTHONSAFEPATH cmd = [sys.executable, '-E', *cmd] proc = subprocess.run(cmd, *args, **kwargs, text=True, stderr=subprocess.PIPE) - self.assertEndsWith(proc.stderr, "\nKeyboardInterrupt\n") + stderr = traceback.strip_exc_timestamps(proc.stderr) + self.assertEndsWith(stderr, "\nKeyboardInterrupt\n") self.assertEqual(proc.returncode, self.EXPECTED_CODE) def test_pymain_run_file(self): diff --git a/Lib/test/test_support.py b/Lib/test/test_support.py index a3129dbcb0a54e..39aaae07d605b1 100644 --- a/Lib/test/test_support.py +++ b/Lib/test/test_support.py @@ -573,6 +573,8 @@ def test_args_from_interpreter_flags(self): ['-X', 'importtime'], ['-X', 'importtime=2'], ['-X', 'showrefcount'], + ['-X', 'traceback_timestamps'], + ['-X', 'traceback_timestamps=ns'], ['-X', 'tracemalloc'], ['-X', 'tracemalloc=3'], ): diff --git a/Lib/test/test_sys.py b/Lib/test/test_sys.py index a729efee18c3a1..9da32e4581a597 100644 --- a/Lib/test/test_sys.py +++ b/Lib/test/test_sys.py @@ -21,6 +21,7 @@ from test.support import threading_helper from test.support import import_helper from test.support import force_not_colorized +from test.support import force_no_traceback_timestamps from test.support import SHORT_TIMEOUT try: from concurrent import interpreters @@ -164,6 +165,7 @@ def f(): class ExceptHookTest(unittest.TestCase): @force_not_colorized + @force_no_traceback_timestamps def test_original_excepthook(self): try: raise ValueError(42) @@ -871,6 +873,7 @@ def test_sys_flags_indexable_attributes(self): for attr_idx, attr in enumerate(indexable_attrs): self.assertHasAttr(sys.flags, attr) attr_type = bool if attr in ("dev_mode", "safe_path") else int + attr_type = str if attr == "traceback_timestamps" else attr_type self.assertEqual(type(getattr(sys.flags, attr)), attr_type, attr) attr_value = getattr(sys.flags, attr) self.assertEqual(sys.flags[attr_idx], attr_value, @@ -886,6 +889,7 @@ def test_sys_flags_name_only_attributes(self): self.assertIsInstance(sys.flags.thread_inherit_context, int|type(None)) self.assertIsInstance(sys.flags.context_aware_warnings, int|type(None)) self.assertIsInstance(sys.flags.lazy_imports, int|type(None)) + self.assertIsInstance(sys.flags.traceback_timestamps, str) def assert_raise_on_new_sys_type(self, sys_attr): # Users are intentionally prevented from creating new instances of @@ -1240,6 +1244,7 @@ def test_getandroidapilevel(self): self.assertGreater(level, 0) @force_not_colorized + @force_no_traceback_timestamps @support.requires_subprocess() def test_sys_tracebacklimit(self): code = """if 1: @@ -1660,13 +1665,13 @@ def inner(): class C(object): pass check(C.__dict__, size('P')) # BaseException - check(BaseException(), size('6Pb')) + check(BaseException(), size('6Pqb')) # UnicodeEncodeError - check(UnicodeEncodeError("", "", 0, 0, ""), size('6Pb 2P2nP')) + check(UnicodeEncodeError("", "", 0, 0, ""), size('6Pqb 2P2nP')) # UnicodeDecodeError - check(UnicodeDecodeError("", b"", 0, 0, ""), size('6Pb 2P2nP')) + check(UnicodeDecodeError("", b"", 0, 0, ""), size('6Pqb 2P2nP')) # UnicodeTranslateError - check(UnicodeTranslateError("", 0, 1, ""), size('6Pb 2P2nP')) + check(UnicodeTranslateError("", 0, 1, ""), size('6Pqb 2P2nP')) # ellipses check(Ellipsis, size('')) # EncodingMap @@ -1924,10 +1929,11 @@ def test_pythontypes(self): # - 'thread_inherit_context' # - 'context_aware_warnings' # - 'lazy_imports' + # - 'traceback_timestamps' # Not needing to increment this every time we add a new field # per GH-122575 would be nice... # Q: What is the actual point of this sys.flags C size derived from PyStructSequence_Field array assertion? - non_sequence_fields = 4 + non_sequence_fields = 5 check(sys.flags, vsize('') + self.P + self.P * (non_sequence_fields + len(sys.flags))) def test_asyncgen_hooks(self): diff --git a/Lib/test/test_threading.py b/Lib/test/test_threading.py index 0ca91ce0d7899d..7fe83b7744a958 100644 --- a/Lib/test/test_threading.py +++ b/Lib/test/test_threading.py @@ -2276,6 +2276,8 @@ def threading_hook(args): threading.excepthook = threading.__excepthook__ recovered_output = run_thread() + default_output = traceback.strip_exc_timestamps(default_output) + recovered_output = traceback.strip_exc_timestamps(recovered_output) self.assertEqual(default_output, recovered_output) self.assertNotEqual(default_output, custom_hook_output) self.assertEqual(custom_hook_output, "Running a thread failed\n") diff --git a/Lib/test/test_traceback.py b/Lib/test/test_traceback.py index 14a08995bf127c..7c9c96c5eb907c 100644 --- a/Lib/test/test_traceback.py +++ b/Lib/test/test_traceback.py @@ -25,6 +25,8 @@ from test.support.script_helper import assert_python_ok, assert_python_failure, make_script from test.support.import_helper import forget from test.support import force_not_colorized, force_not_colorized_test_class +from test.support import force_no_traceback_timestamps +from test.support import force_no_traceback_timestamps_test_class import json import textwrap @@ -50,6 +52,7 @@ LEVENSHTEIN_DATA_FILE = Path(__file__).parent / 'levenshtein_examples.json' +@force_no_traceback_timestamps_test_class class TracebackCases(unittest.TestCase): # For now, a very minimal set of tests. I want to be sure that # formatting of SyntaxErrors works based on changes for 2.1. @@ -519,7 +522,8 @@ def __del__(self): # when the module is unloaded obj = PrintExceptionAtExit() """) - rc, stdout, stderr = assert_python_ok('-c', code) + rc, stdout, stderr = assert_python_ok( + '-c', code, PYTHON_TRACEBACK_TIMESTAMPS="") expected = [b'Traceback (most recent call last):', b' File "", line 8, in __init__', b' x = 1 / 0', @@ -1331,6 +1335,7 @@ def f_with_subscript(): result_lines = self.get_exception(f_with_subscript) self.assertEqual(result_lines, expected_error.splitlines()) + @force_no_traceback_timestamps def test_caret_exception_group(self): # Notably, this covers whether indicators handle margin strings correctly. # (Exception groups use margin strings to display vertical indicators.) @@ -2185,13 +2190,14 @@ def h(count=10): self.assertEqual(actual, expected) @requires_debug_ranges() + @force_no_traceback_timestamps def test_recursive_traceback(self): if self.DEBUG_RANGES: self._check_recursive_traceback_display(traceback.print_exc) else: from _testcapi import exception_print def render_exc(): - exception_print(sys.exception()) + exception_print(sys.exception()) # PyErr_DisplayException self._check_recursive_traceback_display(render_exc) def test_format_stack(self): @@ -3113,6 +3119,7 @@ def f(): @force_not_colorized_test_class +@force_no_traceback_timestamps_test_class class PyExcReportingTests(BaseExceptionReportingTests, unittest.TestCase): # # This checks reporting through the 'traceback' module, with both @@ -3130,6 +3137,7 @@ def get_report(self, e): @force_not_colorized_test_class +@force_no_traceback_timestamps_test_class class CExcReportingTests(BaseExceptionReportingTests, unittest.TestCase): # # This checks built-in reporting by the interpreter. @@ -3796,8 +3804,19 @@ def test_comparison_equivalent_exceptions_are_equal(self): except Exception as e: excs.append(traceback.TracebackException.from_exception(e)) self.assertEqual(excs[0], excs[1]) + + @force_no_traceback_timestamps + def test_comparison_equivalent_exceptions_render_equal_without_timestamps(self): + excs = [] + for _ in range(2): + try: + 1/0 + except Exception as e: + excs.append(traceback.TracebackException.from_exception(e)) + self.assertEqual(excs[0], excs[1]) self.assertEqual(list(excs[0].format()), list(excs[1].format())) + @force_no_traceback_timestamps def test_unhashable(self): class UnhashableException(Exception): def __eq__(self, other): @@ -3863,13 +3882,15 @@ def test_no_locals(self): exc = traceback.TracebackException(Exception, e, tb) self.assertEqual(exc.stack[0].locals, None) + @force_no_traceback_timestamps def test_traceback_header(self): # do not print a traceback header if exc_traceback is None - # see issue #24695 + # see BPO-24695 aka GH-68883 exc = traceback.TracebackException(Exception, Exception("haven"), None) self.assertEqual(list(exc.format()), ["Exception: haven\n"]) @requires_debug_ranges() + @force_no_traceback_timestamps def test_print(self): def f(): x = 12 @@ -3907,6 +3928,7 @@ def test_dont_swallow_cause_or_context_of_falsey_exception(self): self.assertIn(context_message, traceback.format_exception(e)) +@force_no_traceback_timestamps_test_class class TestTracebackException_ExceptionGroups(unittest.TestCase): def setUp(self): super().setUp() @@ -5323,6 +5345,7 @@ def expected(t, m, fn, l, f, E, e, z): ) self.assertIn(expected(**colors), actual) + @force_no_traceback_timestamps def test_colorized_traceback_is_the_default(self): def foo(): 1/0 @@ -5353,6 +5376,7 @@ def expected(t, m, fn, l, f, E, e, z): ] self.assertEqual(actual, expected(**colors)) + @force_no_traceback_timestamps def test_colorized_traceback_from_exception_group(self): def foo(): exceptions = [] diff --git a/Lib/test/test_traceback_timestamps/__init__.py b/Lib/test/test_traceback_timestamps/__init__.py new file mode 100644 index 00000000000000..ca69c98e6dace2 --- /dev/null +++ b/Lib/test/test_traceback_timestamps/__init__.py @@ -0,0 +1,11 @@ +# Test package for traceback timestamps feature + + +def load_tests(loader, tests, pattern): + import unittest + from . import test_basic, test_pickle + + suite = unittest.TestSuite() + suite.addTests(loader.loadTestsFromModule(test_basic)) + suite.addTests(loader.loadTestsFromModule(test_pickle)) + return suite diff --git a/Lib/test/test_traceback_timestamps/test_basic.py b/Lib/test/test_traceback_timestamps/test_basic.py new file mode 100644 index 00000000000000..04fc421ab2a652 --- /dev/null +++ b/Lib/test/test_traceback_timestamps/test_basic.py @@ -0,0 +1,225 @@ +"""Tests for traceback timestamps configuration, output format, and utilities.""" + +import re +import unittest +from traceback import TIMESTAMP_AFTER_EXC_MSG_RE_GROUP + +from test.support import force_not_colorized, script_helper + + +# Script that raises an exception and prints the traceback. +RAISE_SCRIPT = """\ +import traceback +try: + 1/0 +except Exception: + traceback.print_exc() +""" + +# Script that prints sys.flags.traceback_timestamps. +FLAGS_SCRIPT = """\ +import sys +print(repr(sys.flags.traceback_timestamps)) +""" + + +class ConfigurationTests(unittest.TestCase): + """Test -X traceback_timestamps and PYTHON_TRACEBACK_TIMESTAMPS config.""" + + def test_disabled_by_default(self): + result = script_helper.assert_python_ok("-c", RAISE_SCRIPT) + self.assertNotIn(b"<@", result.err) + + def test_env_var_enables(self): + result = script_helper.assert_python_ok( + "-c", RAISE_SCRIPT, PYTHON_TRACEBACK_TIMESTAMPS="us" + ) + self.assertIn(b"<@", result.err) + + def test_flag_precedence_over_env_var(self): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps=ns", + "-c", FLAGS_SCRIPT, + PYTHON_TRACEBACK_TIMESTAMPS="iso", + ) + self.assertEqual(result.out.strip(), b"'ns'") + + def test_flag_no_value_defaults_to_us(self): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps", "-c", FLAGS_SCRIPT + ) + self.assertEqual(result.out.strip(), b"'us'") + + def test_flag_values(self): + """Test sys.flags reflects configured value for each valid option.""" + cases = [ + ([], {}, b"''"), # default + (["-X", "traceback_timestamps=us"], {}, b"'us'"), + (["-X", "traceback_timestamps=ns"], {}, b"'ns'"), + (["-X", "traceback_timestamps=iso"], {}, b"'iso'"), + (["-X", "traceback_timestamps=1"], {}, b"'us'"), + (["-X", "traceback_timestamps=0"], {}, b"''"), + ([], {"PYTHON_TRACEBACK_TIMESTAMPS": "us"}, b"'us'"), + ([], {"PYTHON_TRACEBACK_TIMESTAMPS": "1"}, b"'us'"), + ([], {"PYTHON_TRACEBACK_TIMESTAMPS": "0"}, b"''"), + ] + for args, env, expected in cases: + with self.subTest(args=args, env=env): + result = script_helper.assert_python_ok( + *args, "-c", FLAGS_SCRIPT, **env + ) + self.assertEqual(result.out.strip(), expected) + + def test_invalid_env_var_silently_ignored(self): + result = script_helper.assert_python_ok( + "-c", FLAGS_SCRIPT, PYTHON_TRACEBACK_TIMESTAMPS="invalid" + ) + self.assertEqual(result.out.strip(), b"''") + + def test_invalid_flag_errors(self): + result = script_helper.assert_python_failure( + "-X", "traceback_timestamps=invalid", "-c", FLAGS_SCRIPT + ) + self.assertIn(b"Invalid -X traceback_timestamps=value option", result.err) + + def test_disabled_no_timestamps_in_output(self): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps=0", "-c", RAISE_SCRIPT + ) + self.assertNotIn(b"<@", result.err) + + +class FormatTests(unittest.TestCase): + """Test the three timestamp output formats.""" + + def test_us_format(self): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps=us", "-c", RAISE_SCRIPT + ) + self.assertRegex(result.err, rb"<@\d+\.\d{6}>") + + def test_ns_format(self): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps=ns", "-c", RAISE_SCRIPT + ) + self.assertRegex(result.err, rb"<@\d+ns>") + + def test_iso_format(self): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps=iso", "-c", RAISE_SCRIPT + ) + self.assertRegex( + result.err, + rb"<@\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}Z>", + ) + + +class TimestampPresenceTests(unittest.TestCase): + """Test that timestamps are collected on the right exception types.""" + + PRESENCE_SCRIPT = """\ +import sys, json +exc_name = sys.argv[1] +exc_class = getattr(__builtins__, exc_name, None) or getattr( + __import__('builtins'), exc_name) +try: + raise exc_class("test") +except BaseException as e: + result = { + "type": type(e).__name__, + "ts": e.__timestamp_ns__, + } + print(json.dumps(result)) +""" + + def test_timestamps_collected_when_enabled(self): + for exc_name in ("ValueError", "OSError", "RuntimeError", "KeyError"): + with self.subTest(exc_name): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps=us", + "-c", self.PRESENCE_SCRIPT, exc_name, + ) + import json + output = json.loads(result.out) + self.assertGreater(output["ts"], 0, + f"{exc_name} should have a positive timestamp") + + def test_stop_iteration_excluded(self): + for exc_name in ("StopIteration", "StopAsyncIteration"): + with self.subTest(exc_name): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps=us", + "-c", self.PRESENCE_SCRIPT, exc_name, + ) + import json + output = json.loads(result.out) + self.assertEqual(output["ts"], 0, + f"{exc_name} should not have a timestamp") + + def test_no_timestamps_when_disabled(self): + for exc_name in ("ValueError", "TypeError", "RuntimeError"): + with self.subTest(exc_name): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps=0", + "-c", self.PRESENCE_SCRIPT, exc_name, + ) + import json + output = json.loads(result.out) + self.assertEqual(output["ts"], 0) + + +class StripTimestampsTests(unittest.TestCase): + """Tests for traceback.strip_exc_timestamps().""" + + STRIP_SCRIPT = """\ +import sys, traceback +# Generate a real traceback with timestamps, then strip it. +try: + 1/0 +except Exception: + raw = traceback.format_exc() + +stripped = traceback.strip_exc_timestamps(raw) +# Print both separated by a marker. +sys.stdout.write(raw + "---MARKER---\\n" + stripped) +""" + + @force_not_colorized + def test_strip_removes_timestamps(self): + for mode in ("us", "ns", "iso"): + with self.subTest(mode=mode): + result = script_helper.assert_python_ok( + "-X", f"traceback_timestamps={mode}", + "-c", self.STRIP_SCRIPT, + ) + output = result.out.decode().replace('\r\n', '\n') + parts = output.split("---MARKER---\n") + raw, stripped = parts[0], parts[1] + self.assertIn("<@", raw) + self.assertNotIn("<@", stripped) + self.assertIn("ZeroDivisionError: division by zero", stripped) + + @force_not_colorized + def test_strip_noop_when_disabled(self): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps=0", "-c", self.STRIP_SCRIPT, + ) + output = result.out.decode().replace('\r\n', '\n') + parts = output.split("---MARKER---\n") + raw, stripped = parts[0], parts[1] + self.assertEqual(raw, stripped) + + def test_timestamp_regex_pattern(self): + pattern = re.compile(TIMESTAMP_AFTER_EXC_MSG_RE_GROUP, re.MULTILINE) + # Should match valid formats + self.assertTrue(pattern.search(" <@1234567890.123456>")) + self.assertTrue(pattern.search(" <@1234567890123456789ns>")) + self.assertTrue(pattern.search(" <@2023-04-13T12:34:56.789012Z>")) + # Should not match invalid formats + self.assertFalse(pattern.search("<@>")) + self.assertFalse(pattern.search(" <1234567890.123456>")) + self.assertFalse(pattern.search("<@abc>")) + + +if __name__ == "__main__": + unittest.main() diff --git a/Lib/test/test_traceback_timestamps/test_pickle.py b/Lib/test/test_traceback_timestamps/test_pickle.py new file mode 100644 index 00000000000000..f0ebe2df376932 --- /dev/null +++ b/Lib/test/test_traceback_timestamps/test_pickle.py @@ -0,0 +1,152 @@ +"""Tests for pickle round-trips of exceptions with and without timestamps.""" + +import json +import unittest +from test.support import script_helper + + +# Representative builtin types covering different __reduce__ paths, +# plus both control-flow exclusions. +EXCEPTION_TYPES = [ + "ValueError", + "OSError", + "UnicodeDecodeError", + "SyntaxError", + "StopIteration", + "StopAsyncIteration", +] + +# Subprocess script that creates, pickles, unpickles, and reports on an +# exception. Accepts exc_class_name as argv[1]. Optionally sets a +# nonzero timestamp if argv[2] == "ts". +PICKLE_SCRIPT = r''' +import json, pickle, sys + +name = sys.argv[1] +set_ts = len(sys.argv) > 2 and sys.argv[2] == "ts" + +cls = getattr(__builtins__, name, None) or getattr( + __import__("builtins"), name) + +match name: + case "OSError": + exc = cls("something went wrong") + case "UnicodeDecodeError": + exc = cls("utf-8", b"\xff", 0, 1, "invalid start byte") + case "SyntaxError": + exc = cls("bad", ("test.py", 1, 1, "x")) + case _: + exc = cls("test") + +exc.custom = "val" +if set_ts: + exc.__timestamp_ns__ = 1234567890123456789 + +data = pickle.dumps(exc, protocol=0) +restored = pickle.loads(data) + +print(json.dumps({ + "type": type(restored).__name__, + "custom": getattr(restored, "custom", None), + "ts": restored.__timestamp_ns__, +})) +''' + +# Subprocess script for user-defined exception classes. +USER_PICKLE_SCRIPT = r''' +import json, pickle, sys + +set_ts = len(sys.argv) > 1 and sys.argv[1] == "ts" + +class MyException(Exception): + def __init__(self, msg="MyException"): + super().__init__(msg) + self.data = "custom" + +class MyOSError(OSError): + def __init__(self, *args): + super().__init__(*args) + self.data = "custom" + +class Child(MyException): + def __init__(self, msg="child"): + super().__init__(msg) + self.level = "child" + +results = [] +for cls in (MyException, MyOSError, Child): + exc = cls() + if set_ts: + exc.__timestamp_ns__ = 99999 + + restored = pickle.loads(pickle.dumps(exc, protocol=0)) + results.append({ + "type": type(restored).__name__, + "data": getattr(restored, "data", None), + "level": getattr(restored, "level", None), + "ts": restored.__timestamp_ns__, + "isinstance_base": isinstance(restored, BaseException), + }) + +print(json.dumps(results)) +''' + + +class BuiltinExceptionPickleTests(unittest.TestCase): + + def test_pickle_without_timestamps(self): + for exc_name in EXCEPTION_TYPES: + with self.subTest(exc_name): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps=0", + "-c", PICKLE_SCRIPT, exc_name, + ) + output = json.loads(result.out) + self.assertEqual(output["type"], exc_name) + self.assertEqual(output["custom"], "val") + self.assertEqual(output["ts"], 0) + + def test_pickle_with_timestamps(self): + for exc_name in EXCEPTION_TYPES: + with self.subTest(exc_name): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps=us", + "-c", PICKLE_SCRIPT, exc_name, "ts", + ) + output = json.loads(result.out) + self.assertEqual(output["type"], exc_name) + self.assertEqual(output["custom"], "val") + self.assertEqual(output["ts"], 1234567890123456789) + + +class UserExceptionPickleTests(unittest.TestCase): + + def test_user_exceptions_without_timestamps(self): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps=0", + "-c", USER_PICKLE_SCRIPT, + ) + results = json.loads(result.out) + for entry in results: + with self.subTest(entry["type"]): + self.assertEqual(entry["data"], "custom") + self.assertTrue(entry["isinstance_base"]) + self.assertEqual(entry["ts"], 0) + # Check the inheritance chain child + self.assertEqual(results[2]["level"], "child") + + def test_user_exceptions_with_timestamps(self): + result = script_helper.assert_python_ok( + "-X", "traceback_timestamps=us", + "-c", USER_PICKLE_SCRIPT, "ts", + ) + results = json.loads(result.out) + for entry in results: + with self.subTest(entry["type"]): + self.assertEqual(entry["data"], "custom") + self.assertTrue(entry["isinstance_base"]) + self.assertEqual(entry["ts"], 99999) + + +if __name__ == "__main__": + unittest.main() diff --git a/Lib/test/test_unittest/test_result.py b/Lib/test/test_unittest/test_result.py index 3f44e617303f81..bf82ef02473468 100644 --- a/Lib/test/test_unittest/test_result.py +++ b/Lib/test/test_unittest/test_result.py @@ -282,7 +282,7 @@ def get_exc_info(): result.addFailure(test, exc_info_tuple) result.stopTest(test) - formatted_exc = result.failures[0][1] + formatted_exc = traceback.strip_exc_timestamps(result.failures[0][1]) self.assertEqual(formatted_exc.count("Exception: Loop\n"), 1) def test_addFailure_filter_traceback_frames_chained_exception_cycle(self): @@ -311,7 +311,7 @@ def get_exc_info(): result.addFailure(test, exc_info_tuple) result.stopTest(test) - formatted_exc = result.failures[0][1] + formatted_exc = traceback.strip_exc_timestamps(result.failures[0][1]) self.assertEqual(formatted_exc.count("Exception: A\n"), 1) self.assertEqual(formatted_exc.count("Exception: B\n"), 1) self.assertEqual(formatted_exc.count("Exception: C\n"), 1) diff --git a/Lib/test/test_unittest/test_runner.py b/Lib/test/test_unittest/test_runner.py index a47e2ebb59da02..f85f5160408811 100644 --- a/Lib/test/test_unittest/test_runner.py +++ b/Lib/test/test_unittest/test_runner.py @@ -4,6 +4,7 @@ import pickle import subprocess from test import support +import traceback import unittest from unittest.case import _Outcome @@ -436,7 +437,7 @@ def tearDownClass(cls): ordering.append('tearDownClass') result = runTests(TestableTest) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: CleanUpExc') self.assertEqual(ordering, ['setUpClass', 'setUp', 'cleanup_exc', @@ -459,7 +460,7 @@ def tearDownClass(cls): ordering.append('tearDownClass') result = runTests(TestableTest) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: CleanUpExc') self.assertEqual(ordering, ['setUpClass', 'setUp', 'test', 'cleanup_good', @@ -488,7 +489,7 @@ def tearDownClass(cls): ordering.append('tearDownClass') result = runTests(TestableTest) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: CleanUpExc') self.assertEqual(ordering, ['setUpClass', 'setUp', 'test', @@ -498,9 +499,9 @@ def tearDownClass(cls): class_blow_up = True method_blow_up = False result = runTests(TestableTest) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: ClassExc') - self.assertEqual(result.errors[1][1].splitlines()[-1], + self.assertEqual(get_exception(1, result), f'{CustomErrorRepr}: CleanUpExc') self.assertEqual(ordering, ['setUpClass', 'cleanup_exc']) @@ -509,9 +510,9 @@ def tearDownClass(cls): class_blow_up = False method_blow_up = True result = runTests(TestableTest) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: MethodExc') - self.assertEqual(result.errors[1][1].splitlines()[-1], + self.assertEqual(get_exception(1, result), f'{CustomErrorRepr}: CleanUpExc') self.assertEqual(ordering, ['setUpClass', 'setUp', 'tearDownClass', @@ -532,7 +533,7 @@ def tearDownClass(cls): raise CustomError('TearDownExc') result = runTests(TestableTest) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: TearDownExc') self.assertEqual(ordering, ['setUpClass', 'test', 'tearDownClass', 'cleanup_good']) @@ -604,6 +605,11 @@ class EmptyTest(unittest.TestCase): self.assertIn("\nNO TESTS RAN\n", runner.stream.getvalue()) +def get_exception(index, result): + exception_str = result.errors[index][1].splitlines()[-1] + return traceback.strip_exc_timestamps(exception_str) + + @support.force_not_colorized_test_class class TestModuleCleanUp(ExceptionIsLikeMixin, unittest.TestCase): def test_add_and_do_ModuleCleanup(self): @@ -734,7 +740,7 @@ def tearDownClass(cls): sys.modules['Module'] = Module result = runTests(TestableTest) self.assertEqual(ordering, ['setUpModule', 'cleanup_good']) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: setUpModule Exc') ordering = [] @@ -870,7 +876,7 @@ def tearDownClass(cls): TestableTest.__module__ = 'Module' sys.modules['Module'] = Module result = runTests(TestableTest) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: CleanUpExc') self.assertEqual(ordering, ['setUpModule', 'setUpClass', 'test', 'tearDownClass', 'tearDownModule', @@ -1035,7 +1041,7 @@ def tearDownClass(cls): sys.modules['Module'] = Module result = runTests(TestableTest) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: CleanUpExc') self.assertEqual(ordering, ['setUpModule', 'setUpClass', 'test', 'tearDownClass', @@ -1065,7 +1071,7 @@ def tearDown(self): sys.modules['Module'] = Module result = runTests(TestableTest) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: CleanUpExc') self.assertEqual(ordering, ['setUpModule', 'setUp', 'test', 'tearDown', @@ -1107,7 +1113,7 @@ def tearDownClass(cls): sys.modules['Module'] = Module result = runTests(TestableTest) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: CleanUpExc') self.assertEqual(ordering, ['setUpModule', 'setUpClass', 'setUp', 'test', @@ -1119,9 +1125,9 @@ def tearDownClass(cls): class_blow_up = False method_blow_up = False result = runTests(TestableTest) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: ModuleExc') - self.assertEqual(result.errors[1][1].splitlines()[-1], + self.assertEqual(get_exception(1, result), f'{CustomErrorRepr}: CleanUpExc') self.assertEqual(ordering, ['setUpModule', 'cleanup_exc']) @@ -1130,9 +1136,9 @@ def tearDownClass(cls): class_blow_up = True method_blow_up = False result = runTests(TestableTest) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: ClassExc') - self.assertEqual(result.errors[1][1].splitlines()[-1], + self.assertEqual(get_exception(1, result), f'{CustomErrorRepr}: CleanUpExc') self.assertEqual(ordering, ['setUpModule', 'setUpClass', 'tearDownModule', 'cleanup_exc']) @@ -1142,9 +1148,9 @@ def tearDownClass(cls): class_blow_up = False method_blow_up = True result = runTests(TestableTest) - self.assertEqual(result.errors[0][1].splitlines()[-1], + self.assertEqual(get_exception(0, result), f'{CustomErrorRepr}: MethodExc') - self.assertEqual(result.errors[1][1].splitlines()[-1], + self.assertEqual(get_exception(1, result), f'{CustomErrorRepr}: CleanUpExc') self.assertEqual(ordering, ['setUpModule', 'setUpClass', 'setUp', 'tearDownClass', 'tearDownModule', diff --git a/Lib/test/test_warnings/__init__.py b/Lib/test/test_warnings/__init__.py index a6af5057cc8968..4f0ca09388a948 100644 --- a/Lib/test/test_warnings/__init__.py +++ b/Lib/test/test_warnings/__init__.py @@ -14,7 +14,7 @@ from test.support import import_helper from test.support import os_helper from test.support import warnings_helper -from test.support import force_not_colorized +from test.support import force_not_colorized, force_no_traceback_timestamps from test.support.script_helper import assert_python_ok, assert_python_failure from test.test_warnings.data import package_helper @@ -1474,6 +1474,7 @@ def test_envvar_and_command_line(self): b"['ignore::DeprecationWarning', 'ignore::UnicodeWarning']") @force_not_colorized + @force_no_traceback_timestamps def test_conflicting_envvar_and_command_line(self): rc, stdout, stderr = assert_python_failure("-Werror::DeprecationWarning", "-c", "import sys, warnings; sys.stdout.write(str(sys.warnoptions)); " diff --git a/Lib/test/test_wsgiref.py b/Lib/test/test_wsgiref.py index 3379df37d38ca8..42beb8e0c8decf 100644 --- a/Lib/test/test_wsgiref.py +++ b/Lib/test/test_wsgiref.py @@ -18,6 +18,7 @@ import os import re import signal +import traceback import sys import threading import unittest @@ -153,7 +154,7 @@ def bad_app(environ,start_response): b"A server error occurred. Please contact the administrator." ) self.assertEqual( - err.splitlines()[-2], + traceback.strip_exc_timestamps(err).splitlines()[-2], "AssertionError: Headers (('Content-Type', 'text/plain')) must" " be of type list: " ) @@ -177,7 +178,7 @@ def bad_app(environ, start_response): self.assertEndsWith(out, b"A server error occurred. Please contact the administrator." ) - self.assertEqual(err.splitlines()[-2], exc_message) + self.assertEqual(traceback.strip_exc_timestamps(err).splitlines()[-2], exc_message) def test_wsgi_input(self): def bad_app(e,s): @@ -189,7 +190,7 @@ def bad_app(e,s): b"A server error occurred. Please contact the administrator." ) self.assertEqual( - err.splitlines()[-2], "AssertionError" + traceback.strip_exc_timestamps(err).splitlines()[-2], "AssertionError" ) def test_bytes_validation(self): diff --git a/Lib/traceback.py b/Lib/traceback.py index 956cab49131990..52453b3d42da63 100644 --- a/Lib/traceback.py +++ b/Lib/traceback.py @@ -28,7 +28,7 @@ 'format_tb', 'print_exc', 'format_exc', 'print_exception', 'print_last', 'print_stack', 'print_tb', 'clear_frames', 'FrameSummary', 'StackSummary', 'TracebackException', - 'walk_stack', 'walk_tb', 'print_list'] + 'walk_stack', 'walk_tb', 'print_list', 'strip_exc_timestamps'] # # Formatting and printing lists of traceback lines. @@ -138,8 +138,9 @@ def print_exception(exc, /, value=_sentinel, tb=_sentinel, limit=None, \ position of the error. """ colorize = kwargs.get("colorize", False) + no_timestamp = kwargs.get("no_timestamp", False) value, tb = _parse_value_tb(exc, value, tb) - te = TracebackException(type(value), value, tb, limit=limit, compact=True) + te = TracebackException(type(value), value, tb, limit=limit, compact=True, no_timestamp=no_timestamp) te.print(file=file, chain=chain, colorize=colorize) @@ -164,8 +165,9 @@ def format_exception(exc, /, value=_sentinel, tb=_sentinel, limit=None, \ printed as does print_exception(). """ colorize = kwargs.get("colorize", False) + no_timestamp = kwargs.get("no_timestamp", False) value, tb = _parse_value_tb(exc, value, tb) - te = TracebackException(type(value), value, tb, limit=limit, compact=True) + te = TracebackException(type(value), value, tb, limit=limit, compact=True, no_timestamp=no_timestamp) return list(te.format(chain=chain, colorize=colorize)) @@ -185,25 +187,75 @@ def format_exception_only(exc, /, value=_sentinel, *, show_group=False, **kwargs well, recursively, with indentation relative to their nesting depth. """ colorize = kwargs.get("colorize", False) + no_timestamp = kwargs.get("no_timestamp", False) if value is _sentinel: value = exc - te = TracebackException(type(value), value, None, compact=True) + te = TracebackException(type(value), value, None, compact=True, no_timestamp=no_timestamp) return list(te.format_exception_only(show_group=show_group, colorize=colorize)) +match _TIMESTAMP_FORMAT := getattr(sys.flags, "traceback_timestamps", ""): + case "" | "0": + _TIMESTAMP_FORMAT = "" + case "us" | "1": + def _timestamp_formatter(ns): + return f"<@{ns/1e9:.6f}>" + case "ns": + def _timestamp_formatter(ns): + return f"<@{ns}ns>" + case "iso": + def _timestamp_formatter(ns): + # Less logic in a critical path than using datetime. + from time import strftime, gmtime + seconds = ns / 1e9 + # Use gmtime for UTC time + timestr = strftime("%Y-%m-%dT%H:%M:%S", gmtime(seconds)) + fractional = f"{seconds - int(seconds):.6f}"[2:] # Get just the decimal part + return f"<@{timestr}.{fractional}Z>" # Z suffix indicates UTC/Zulu time + case _: + raise ValueError(f"Invalid sys.flags.traceback_timestamp={_TIMESTAMP_FORMAT!r}") + + +# The regular expression to match timestamps as formatted in tracebacks. +# Not compiled to avoid importing the re module by default. +TIMESTAMP_AFTER_EXC_MSG_RE_GROUP = r"(?P <@[0-9:.Tsnu-]{17,26}Z?>)" + + +def strip_exc_timestamps(output): + """Remove exception timestamps from output; for use by tests.""" + import re + if isinstance(output, str): + pattern = TIMESTAMP_AFTER_EXC_MSG_RE_GROUP + empty = "" + else: + pattern = TIMESTAMP_AFTER_EXC_MSG_RE_GROUP.encode() + empty = b"" + return re.sub(pattern, empty, output, flags=re.MULTILINE) + + # -- not official API but folk probably use these two functions. -def _format_final_exc_line(etype, value, *, insert_final_newline=True, colorize=False): +def _format_final_exc_line(etype, value, *, insert_final_newline=True, colorize=False, timestamp_ns=0): valuestr = _safe_string(value, 'exception') - end_char = "\n" if insert_final_newline else "" + try: + ts = _timestamp_formatter(timestamp_ns) if timestamp_ns else "" + except Exception: + ts = "" + end = f"\n" if insert_final_newline else "" if colorize: theme = _colorize.get_theme(force_color=True).traceback + end = f" {_colorize.ANSIColors.GREY}{ts}{theme.reset}{end}" if ts else end + if value is None or not valuestr: + line = f"{theme.type}{etype}{theme.reset}{end}" + else: + line = f"{theme.type}{etype}{theme.reset}: {theme.message}{valuestr}{theme.reset}{end}" else: theme = _colorize.get_theme(force_no_color=True).traceback - if value is None or not valuestr: - line = f"{theme.type}{etype}{theme.reset}{end_char}" - else: - line = f"{theme.type}{etype}{theme.reset}: {theme.message}{valuestr}{theme.reset}{end_char}" + end = f" {ts}{end}" if ts else end + if value is None or not valuestr: + line = f"{etype}{end}" + else: + line = f"{etype}: {valuestr}{end}" return line @@ -1035,10 +1087,12 @@ class TracebackException: - :attr:`__cause__` A TracebackException of the original *__cause__*. - :attr:`__context__` A TracebackException of the original *__context__*. + - :attr:`__notes__` A reference to the original *__notes__* list. - :attr:`exceptions` For exception groups - a list of TracebackException instances for the nested *exceptions*. ``None`` for other exceptions. - :attr:`__suppress_context__` The *__suppress_context__* value from the original exception. + - :attr:`_timestamp_ns` When the exception was created if enabled, or 0. - :attr:`stack` A `StackSummary` representing the traceback. - :attr:`exc_type` (deprecated) The class of the original traceback. - :attr:`exc_type_str` String display of exc_type @@ -1059,7 +1113,8 @@ class TracebackException: def __init__(self, exc_type, exc_value, exc_traceback, *, limit=None, lookup_lines=True, capture_locals=False, compact=False, - max_group_width=15, max_group_depth=10, save_exc_type=True, _seen=None): + max_group_width=15, max_group_depth=10, save_exc_type=True, + no_timestamp=False, _seen=None): # NB: we need to accept exc_traceback, exc_value, exc_traceback to # permit backwards compat with the existing API, otherwise we # need stub thunk objects just to glue it together. @@ -1093,9 +1148,12 @@ def __init__(self, exc_type, exc_value, exc_traceback, *, limit=None, if exc_type is not None: self.exc_type_qualname = exc_type.__qualname__ self.exc_type_module = exc_type.__module__ + self._timestamp_ns = (exc_value.__timestamp_ns__ + if _TIMESTAMP_FORMAT and not no_timestamp else 0) else: self.exc_type_qualname = None self.exc_type_module = None + self._timestamp_ns = 0 if exc_type and issubclass(exc_type, SyntaxError): # Handle SyntaxError's specially @@ -1267,7 +1325,20 @@ def _load_lines(self): def __eq__(self, other): if isinstance(other, TracebackException): - return self.__dict__ == other.__dict__ + # It is unlikely anything would ever be equal when timestamp + # collection is enabled without this. We avoid extra work when + # it is not enabled. + if self._timestamp_ns: + s_dict = self.__dict__.copy() + s_dict["_timestamp_ns"] = 0 + else: + s_dict = self.__dict__ + if other._timestamp_ns: + o_dict = other.__dict__.copy() + o_dict["_timestamp_ns"] = 0 + else: + o_dict = other.__dict__ + return s_dict == o_dict return NotImplemented def __str__(self): @@ -1294,7 +1365,7 @@ def format_exception_only(self, *, show_group=False, _depth=0, **kwargs): indent = 3 * _depth * ' ' if not self._have_exc_type: - yield indent + _format_final_exc_line(None, self._str, colorize=colorize) + yield indent + _format_final_exc_line(None, self._str, colorize=colorize, timestamp_ns=self._timestamp_ns) return stype = self.exc_type_str @@ -1302,14 +1373,14 @@ def format_exception_only(self, *, show_group=False, _depth=0, **kwargs): if _depth > 0: # Nested exceptions needs correct handling of multiline messages. formatted = _format_final_exc_line( - stype, self._str, insert_final_newline=False, colorize=colorize + stype, self._str, insert_final_newline=False, colorize=colorize, timestamp_ns=self._timestamp_ns ).split('\n') yield from [ indent + l + '\n' for l in formatted ] else: - yield _format_final_exc_line(stype, self._str, colorize=colorize) + yield _format_final_exc_line(stype, self._str, colorize=colorize, timestamp_ns=self._timestamp_ns) else: yield from [indent + l for l in self._format_syntax_error(stype, colorize=colorize)] diff --git a/Makefile.pre.in b/Makefile.pre.in index 120a6add38507f..964a294fc507b6 100644 --- a/Makefile.pre.in +++ b/Makefile.pre.in @@ -2763,6 +2763,7 @@ TESTSUBDIRS= idlelib/idle_test \ test/test_tools \ test/test_tools/i18n_data \ test/test_tools/msgfmt_data \ + test/test_traceback_timestamps \ test/test_ttk \ test/test_unittest \ test/test_unittest/namespace_test_pkg \ diff --git a/Misc/NEWS.d/next/Core_and_Builtins/2026-03-15-19-30-07.gh-issue-132502.OGTJuV.rst b/Misc/NEWS.d/next/Core_and_Builtins/2026-03-15-19-30-07.gh-issue-132502.OGTJuV.rst new file mode 100644 index 00000000000000..83e0e26e6f016d --- /dev/null +++ b/Misc/NEWS.d/next/Core_and_Builtins/2026-03-15-19-30-07.gh-issue-132502.OGTJuV.rst @@ -0,0 +1,5 @@ +Add optional timestamps to exception tracebacks (:pep:`829`). When enabled +via :envvar:`PYTHON_TRACEBACK_TIMESTAMPS` or :option:`-X +traceback_timestamps <-X>`, each exception records its instantiation time in +``__timestamp_ns__`` and formatted tracebacks display the timestamp +alongside the exception message. diff --git a/Objects/exceptions.c b/Objects/exceptions.c index f5edc286243ee1..ed756b131e4809 100644 --- a/Objects/exceptions.c +++ b/Objects/exceptions.c @@ -33,6 +33,16 @@ get_exc_state(void) } +static bool +should_collect_traceback_timestamps(void) +{ + /* Unset or empty means disabled. */ + wchar_t *traceback_timestamps = ( + _PyInterpreterState_GET()->config.traceback_timestamps); + return traceback_timestamps && traceback_timestamps[0] != '\0'; +} + + /* NOTE: If the exception class hierarchy changes, don't forget to update * Lib/test/exception_hierarchy.txt */ @@ -58,6 +68,7 @@ BaseException_new(PyTypeObject *type, PyObject *args, PyObject *kwds) /* the dict is created on the fly in PyObject_GenericSetAttr */ self->dict = NULL; self->notes = NULL; + self->timestamp_ns = 0; self->traceback = self->cause = self->context = NULL; self->suppress_context = 0; @@ -75,6 +86,17 @@ BaseException_new(PyTypeObject *type, PyObject *args, PyObject *kwds) return (PyObject *)self; } +static inline void BaseException_init_timestamp(PyBaseExceptionObject *self) +{ + if (!should_collect_traceback_timestamps() || + Py_IS_TYPE(self, (PyTypeObject *)PyExc_StopIteration) || + Py_IS_TYPE(self, (PyTypeObject *)PyExc_StopAsyncIteration)) { + self->timestamp_ns = 0; /* fast; frequent non-error control flow. */ + } else { + PyTime_TimeRaw(&self->timestamp_ns); /* fills in 0 on failure. */ + } +} + static int BaseException_init(PyObject *op, PyObject *args, PyObject *kwds) { @@ -83,6 +105,7 @@ BaseException_init(PyObject *op, PyObject *args, PyObject *kwds) return -1; Py_XSETREF(self->args, Py_NewRef(args)); + BaseException_init_timestamp(self); return 0; } @@ -105,6 +128,7 @@ BaseException_vectorcall(PyObject *type_obj, PyObject * const*args, // The dict is created on the fly in PyObject_GenericSetAttr() self->dict = NULL; self->notes = NULL; + BaseException_init_timestamp(self); // self.timestamp_ns = ... self->traceback = NULL; self->cause = NULL; self->context = NULL; @@ -202,6 +226,26 @@ BaseException_repr(PyObject *op) /* Pickling support */ +/* Returns dict on success, after having maybe added a __timestamp_ns__ key; + NULL on error. dict does not have to be self->dict as the getstate use + case often uses a copy. No key is added if its value would be 0. */ +static PyObject* BaseException_add_timestamp_to_dict(PyBaseExceptionObject *self, PyObject *dict) +{ + assert(dict != NULL); + if (self->timestamp_ns <= 0) { + return dict; + } + PyObject *ts = PyLong_FromLongLong(self->timestamp_ns); + if (!ts) + return NULL; + if (PyDict_SetItem(dict, &_Py_ID(__timestamp_ns__), ts) == -1) { + Py_DECREF(ts); + return NULL; + } + Py_DECREF(ts); + return dict; +} + /*[clinic input] @critical_section BaseException.__reduce__ @@ -211,10 +255,29 @@ static PyObject * BaseException___reduce___impl(PyBaseExceptionObject *self) /*[clinic end generated code: output=af87c1247ef98748 input=283be5a10d9c964f]*/ { - if (self->args && self->dict) - return PyTuple_Pack(3, Py_TYPE(self), self->args, self->dict); - else + PyObject *dict = NULL; + + /* Only create and include a dict if we have a timestamp to store or + * if the exception already has custom attributes in its dict. */ + if (self->timestamp_ns > 0 || (self->dict && PyDict_GET_SIZE(self->dict) > 0)) { + if (!self->dict) { + self->dict = PyDict_New(); + if (self->dict == NULL) { + return NULL; + } + } + if (!BaseException_add_timestamp_to_dict(self, self->dict)) { + return NULL; + } + dict = self->dict; + } + + /* Include dict in the pickle tuple only if we have one with content */ + if (dict) { + return PyTuple_Pack(3, Py_TYPE(self), self->args, dict); + } else { return PyTuple_Pack(2, Py_TYPE(self), self->args); + } } /* @@ -596,6 +659,8 @@ PyExceptionClass_Name(PyObject *ob) static struct PyMemberDef BaseException_members[] = { {"__suppress_context__", Py_T_BOOL, offsetof(PyBaseExceptionObject, suppress_context)}, + {"__timestamp_ns__", Py_T_LONGLONG, + offsetof(PyBaseExceptionObject, timestamp_ns)}, {NULL} }; @@ -1877,30 +1942,27 @@ ImportError_getstate(PyObject *op) { PyImportErrorObject *self = PyImportErrorObject_CAST(op); PyObject *dict = self->dict; - if (self->name || self->path || self->name_from) { - dict = dict ? PyDict_Copy(dict) : PyDict_New(); - if (dict == NULL) - return NULL; - if (self->name && PyDict_SetItem(dict, &_Py_ID(name), self->name) < 0) { - Py_DECREF(dict); - return NULL; - } - if (self->path && PyDict_SetItem(dict, &_Py_ID(path), self->path) < 0) { - Py_DECREF(dict); - return NULL; - } - if (self->name_from && PyDict_SetItem(dict, &_Py_ID(name_from), self->name_from) < 0) { - Py_DECREF(dict); - return NULL; - } - return dict; + dict = dict ? PyDict_Copy(dict) : PyDict_New(); + if (dict == NULL) { + return NULL; } - else if (dict) { - return Py_NewRef(dict); + if (!BaseException_add_timestamp_to_dict((PyBaseExceptionObject *)self, dict)) { + Py_DECREF(dict); + return NULL; } - else { - Py_RETURN_NONE; + if (self->name && PyDict_SetItem(dict, &_Py_ID(name), self->name) < 0) { + Py_DECREF(dict); + return NULL; } + if (self->path && PyDict_SetItem(dict, &_Py_ID(path), self->path) < 0) { + Py_DECREF(dict); + return NULL; + } + if (self->name_from && PyDict_SetItem(dict, &_Py_ID(name_from), self->name_from) < 0) { + Py_DECREF(dict); + return NULL; + } + return dict; } /* Pickling support */ @@ -1911,11 +1973,20 @@ ImportError_reduce(PyObject *self, PyObject *Py_UNUSED(ignored)) PyObject *state = ImportError_getstate(self); if (state == NULL) return NULL; + PyBaseExceptionObject *exc = PyBaseExceptionObject_CAST(self); - if (state == Py_None) - res = PyTuple_Pack(2, Py_TYPE(self), exc->args); - else + PyImportErrorObject *import_exc = PyImportErrorObject_CAST(self); + + /* Only include state dict if it has content beyond an empty timestamp */ + bool has_content = (exc->timestamp_ns > 0 || + import_exc->name || import_exc->path || import_exc->name_from || + (import_exc->dict && PyDict_GET_SIZE(import_exc->dict) > 0)); + + if (has_content) { res = PyTuple_Pack(3, Py_TYPE(self), exc->args, state); + } else { + res = PyTuple_Pack(2, Py_TYPE(self), exc->args); + } Py_DECREF(state); return res; } @@ -2274,6 +2345,8 @@ OSError_init(PyObject *op, PyObject *args, PyObject *kwds) PyObject *winerror = NULL; #endif + BaseException_init_timestamp((PyBaseExceptionObject *)self); + if (!oserror_use_init(Py_TYPE(self))) /* Everything already done in OSError_new */ return 0; @@ -2418,10 +2491,29 @@ OSError_reduce(PyObject *op, PyObject *Py_UNUSED(ignored)) } else Py_INCREF(args); - if (self->dict) - res = PyTuple_Pack(3, Py_TYPE(self), args, self->dict); - else + PyObject *dict = NULL; + PyBaseExceptionObject *base_self = (PyBaseExceptionObject*)self; + + /* Only create and include a dict if we have a timestamp to store or + * if the exception already has custom attributes in its dict. */ + if (base_self->timestamp_ns > 0 || (self->dict && PyDict_GET_SIZE(self->dict) > 0)) { + if (!self->dict) { + self->dict = PyDict_New(); + } + if (!self->dict || + !BaseException_add_timestamp_to_dict(base_self, self->dict)) { + Py_DECREF(args); + return NULL; + } + dict = self->dict; + } + + /* Include dict in the pickle tuple only if we have one with content */ + if (dict) { + res = PyTuple_Pack(3, Py_TYPE(self), args, dict); + } else { res = PyTuple_Pack(2, Py_TYPE(self), args); + } Py_DECREF(args); return res; } @@ -2717,28 +2809,30 @@ AttributeError_getstate(PyObject *op, PyObject *Py_UNUSED(ignored)) { PyAttributeErrorObject *self = PyAttributeErrorObject_CAST(op); PyObject *dict = self->dict; - if (self->name || self->args) { - dict = dict ? PyDict_Copy(dict) : PyDict_New(); - if (dict == NULL) { - return NULL; - } - if (self->name && PyDict_SetItemString(dict, "name", self->name) < 0) { - Py_DECREF(dict); - return NULL; - } - /* We specifically are not pickling the obj attribute since there are many - cases where it is unlikely to be picklable. See GH-103352. - */ - if (self->args && PyDict_SetItemString(dict, "args", self->args) < 0) { - Py_DECREF(dict); - return NULL; - } - return dict; + dict = dict ? PyDict_Copy(dict) : PyDict_New(); + if (dict == NULL) { + return NULL; } - else if (dict) { - return Py_NewRef(dict); + + /* Always add timestamp first if present */ + if (!BaseException_add_timestamp_to_dict((PyBaseExceptionObject*)self, dict)) { + Py_DECREF(dict); + return NULL; } - Py_RETURN_NONE; + + /* Add AttributeError-specific attributes */ + if (self->name && PyDict_SetItemString(dict, "name", self->name) < 0) { + Py_DECREF(dict); + return NULL; + } + /* We specifically are not pickling the obj attribute since there are many + cases where it is unlikely to be picklable. See GH-103352. + */ + if (self->args && PyDict_SetItemString(dict, "args", self->args) < 0) { + Py_DECREF(dict); + return NULL; + } + return dict; } static PyObject * @@ -2750,6 +2844,9 @@ AttributeError_reduce(PyObject *op, PyObject *Py_UNUSED(ignored)) } PyAttributeErrorObject *self = PyAttributeErrorObject_CAST(op); + + /* AttributeError always includes state dict for compatibility with Python 3.13 behavior. + * The getstate method always includes 'args' in the returned dict. */ PyObject *return_value = PyTuple_Pack(3, Py_TYPE(self), self->args, state); Py_DECREF(state); return return_value; diff --git a/Python/initconfig.c b/Python/initconfig.c index caf42f5247c2f2..dd0b0beefd939b 100644 --- a/Python/initconfig.c +++ b/Python/initconfig.c @@ -138,6 +138,7 @@ static const PyConfigSpec PYCONFIG_SPEC[] = { #endif SPEC(buffered_stdio, BOOL, READ_ONLY, NO_SYS), SPEC(check_hash_pycs_mode, WSTR, READ_ONLY, NO_SYS), + SPEC(traceback_timestamps, WSTR_OPT, READ_ONLY, NO_SYS), SPEC(code_debug_ranges, BOOL, READ_ONLY, NO_SYS), SPEC(configure_c_stdio, BOOL, READ_ONLY, NO_SYS), SPEC(dev_mode, BOOL, READ_ONLY, NO_SYS), // sys.flags.dev_mode @@ -302,6 +303,7 @@ file : program read from script file\n\ arg ...: arguments passed to program in sys.argv[1:]\n\ "; +/* Please keep sorted by -X option name, ignoring -s and _s */ static const char usage_xoptions[] = "\ The following implementation-specific options are available:\n\ -X context_aware_warnings=[0|1]: if true (1) then the warnings module will\n\ @@ -361,6 +363,10 @@ The following implementation-specific options are available:\n\ PYTHON_TLBC\n" #endif "\ +-X traceback_timestamps=[us|ns|iso|0|1]: display timestamp in tracebacks when\n\ + exception occurs; \"us\" shows microseconds;\n\ + \"ns\" shows raw nanoseconds; \"iso\" shows ISO-8601 format; \"0\" disables timestamps;\n\ + \"1\" is equivalent to \"us\"; also PYTHON_TRACEBACK_TIMESTAMPS\n\ -X tracemalloc[=N]: trace Python memory allocations; N sets a traceback limit\n\ of N frames (default: 1); also PYTHONTRACEMALLOC=N\n\ -X utf8[=0|1]: enable (1) or disable (0) UTF-8 mode; also PYTHONUTF8\n\ @@ -369,6 +375,7 @@ The following implementation-specific options are available:\n\ "; /* Envvars that don't have equivalent command-line options are listed first */ +/* Please keep sections sorted by environment variable name, ignoring _s */ static const char usage_envvars[] = "Environment variables that change behavior:\n" "PYTHONASYNCIODEBUG: enable asyncio debug mode\n" @@ -453,6 +460,8 @@ static const char usage_envvars[] = #ifdef Py_GIL_DISABLED "PYTHON_TLBC : when set to 0, disables thread-local bytecode (-X tlbc)\n" #endif +"PYTHON_TRACEBACK_TIMESTAMPS: collect and display timestamps in tracebacks\n" +" (-X traceback_timestamps)\n" "PYTHONTRACEMALLOC: trace Python memory allocations (-X tracemalloc)\n" "PYTHONUNBUFFERED: disable stdout/stderr buffering (-u)\n" "PYTHONUTF8 : control the UTF-8 mode (-X utf8)\n" @@ -942,6 +951,7 @@ config_check_consistency(const PyConfig *config) /* -c and -m options are exclusive */ assert(!(config->run_command != NULL && config->run_module != NULL)); assert(config->check_hash_pycs_mode != NULL); + assert(config->traceback_timestamps != NULL); assert(config->_install_importlib >= 0); assert(config->pathconfig_warnings >= 0); assert(config->_is_python_build >= 0); @@ -1005,6 +1015,7 @@ PyConfig_Clear(PyConfig *config) CLEAR(config->run_module); CLEAR(config->run_filename); CLEAR(config->check_hash_pycs_mode); + CLEAR(config->traceback_timestamps); #ifdef Py_DEBUG CLEAR(config->run_presite); #endif @@ -1047,6 +1058,7 @@ _PyConfig_InitCompatConfig(PyConfig *config) config->buffered_stdio = -1; config->_install_importlib = 1; config->check_hash_pycs_mode = NULL; + config->traceback_timestamps = NULL; config->pathconfig_warnings = -1; config->_init_main = 1; #ifdef MS_WINDOWS @@ -2073,6 +2085,80 @@ config_init_tlbc(PyConfig *config) #endif } +static inline int +is_valid_timestamp_format(const wchar_t *value) +{ + return (wcscmp(value, L"us") == 0 || + wcscmp(value, L"ns") == 0 || + wcscmp(value, L"iso") == 0 || + wcscmp(value, L"0") == 0 || + wcscmp(value, L"1") == 0); +} + +static inline const wchar_t * +normalize_timestamp_format(const wchar_t *value) +{ + if (wcscmp(value, L"1") == 0) { + /* Treat "1" as "us" for backward compatibility */ + return L"us"; + } + if (wcscmp(value, L"0") == 0) { + /* "0" means disable the feature. */ + return L""; + } + return value; +} + +static PyStatus +config_init_traceback_timestamps(PyConfig *config) +{ + /* Handle environment variable first */ + const char *env = config_get_env(config, "PYTHON_TRACEBACK_TIMESTAMPS"); + if (env && env[0] != '\0') { + wchar_t *wenv = Py_DecodeLocale(env, NULL); + if (wenv == NULL) { + return _PyStatus_NO_MEMORY(); + } + + /* For environment variables, silently ignore invalid values */ + if (is_valid_timestamp_format(wenv)) { + const wchar_t *normalized = normalize_timestamp_format(wenv); + PyStatus status = PyConfig_SetString( + config, &config->traceback_timestamps, normalized); + PyMem_RawFree(wenv); + if (_PyStatus_EXCEPTION(status)) { + return status; + } + } else { + PyMem_RawFree(wenv); + } + } + + /* -X option overrides environment variable */ + const wchar_t *xoption = config_get_xoption_value( + config, L"traceback_timestamps"); + if (xoption != NULL) { + /* If just -X traceback_timestamps with no =, use "us" as default */ + const wchar_t *value = (*xoption != '\0') ? xoption : L"us"; + + /* Validate command line option values, error out if invalid */ + if (is_valid_timestamp_format(value)) { + const wchar_t *normalized = normalize_timestamp_format(value); + PyStatus status = PyConfig_SetString( + config, &config->traceback_timestamps, normalized); + if (_PyStatus_EXCEPTION(status)) { + return status; + } + } else { + return PyStatus_Error( + "Invalid -X traceback_timestamps=value option. Valid " + "values are: us, ns, iso, 0, 1 or empty."); + } + } + + return _PyStatus_OK(); +} + static PyStatus config_init_perf_profiling(PyConfig *config) { @@ -2396,6 +2482,14 @@ config_read_complex_options(PyConfig *config) } PyStatus status; + + if (config->traceback_timestamps == NULL) { + status = config_init_traceback_timestamps(config); + if (_PyStatus_EXCEPTION(status)) { + return status; + } + } + if (config->import_time < 0) { status = config_init_import_time(config); if (_PyStatus_EXCEPTION(status)) { @@ -2845,6 +2939,13 @@ config_read(PyConfig *config, int compute_path_config) return status; } } + if (config->traceback_timestamps == NULL) { + status = PyConfig_SetString(config, &config->traceback_timestamps, + L""); + if (_PyStatus_EXCEPTION(status)) { + return status; + } + } if (config->configure_c_stdio < 0) { config->configure_c_stdio = 1; diff --git a/Python/pythonrun.c b/Python/pythonrun.c index a21f494dc69d82..356dd94257d64f 100644 --- a/Python/pythonrun.c +++ b/Python/pythonrun.c @@ -17,6 +17,7 @@ #include "pycore_fileutils.h" // _PyFile_Flush #include "pycore_import.h" // _PyImport_GetImportlibExternalLoader() #include "pycore_interp.h" // PyInterpreterState.importlib +#include "pycore_long.h" // _PyLong_IsZero() #include "pycore_object.h" // _PyDebug_PrintTotalRefs() #include "pycore_parser.h" // _PyParser_ASTFromString() #include "pycore_pyerrors.h" // _PyErr_GetRaisedException() @@ -950,6 +951,36 @@ print_exception_message(struct exception_print_context *ctx, PyObject *type, if (res < 0) { return -1; } + + /* attempt to append the exception timestamp if configured to do so + * in the traceback module. non-fatal if any of this fails. */ + PyObject *timestamp_formatter = PyImport_ImportModuleAttr( + &_Py_ID(traceback), + &_Py_ID(_timestamp_formatter)); + if (timestamp_formatter && PyCallable_Check(timestamp_formatter)) { + PyObject *ns_obj = PyObject_GetAttr(value, &_Py_ID(__timestamp_ns__)); + if (ns_obj && PyLong_Check(ns_obj) && !_PyLong_IsZero((PyLongObject *)ns_obj)) { + PyObject* ns_str = PyObject_CallOneArg(timestamp_formatter, ns_obj); + if (ns_str) { + if (PyFile_WriteString(" ", f) >= 0) { + if (PyFile_WriteObject(ns_str, f, Py_PRINT_RAW) < 0) { +#ifdef Py_DEBUG + PyFile_WriteString("", f); +#endif + } + } + Py_DECREF(ns_str); + } else { + PyErr_Clear(); + } + } else { + PyErr_Clear(); + } + Py_XDECREF(ns_obj); + } else { + PyErr_Clear(); + } + Py_XDECREF(timestamp_formatter); } return 0; @@ -1141,9 +1172,9 @@ _PyErr_Display(PyObject *file, PyObject *unused, PyObject *value, PyObject *tb) } // Try first with the stdlib traceback module - PyObject *print_exception_fn = PyImport_ImportModuleAttrString( - "traceback", - "_print_exception_bltin"); + PyObject *print_exception_fn = PyImport_ImportModuleAttr( + &_Py_ID(traceback), + &_Py_ID(_print_exception_bltin)); if (print_exception_fn == NULL || !PyCallable_Check(print_exception_fn)) { Py_XDECREF(print_exception_fn); goto fallback; diff --git a/Python/sysmodule.c b/Python/sysmodule.c index 646b8a1c3c3a84..3a330f8ed1b137 100644 --- a/Python/sysmodule.c +++ b/Python/sysmodule.c @@ -3502,6 +3502,7 @@ static PyStructSequence_Field flags_fields[] = { {"thread_inherit_context", "-X thread_inherit_context"}, {"context_aware_warnings", "-X context_aware_warnings"}, {"lazy_imports", "-X lazy_imports"}, + {"traceback_timestamps", "-X traceback_timestamps"}, {0} }; @@ -3607,6 +3608,19 @@ set_flags_from_config(PyInterpreterState *interp, PyObject *flags) SetFlag(config->thread_inherit_context); SetFlag(config->context_aware_warnings); SetFlag(config->lazy_imports); + PyObject *ts_str; + if (config->traceback_timestamps != NULL && config->traceback_timestamps[0] != L'\0') { + ts_str = PyUnicode_FromWideChar(config->traceback_timestamps, -1); + if (ts_str == NULL) { + return -1; + } + } + else { + ts_str = PyUnicode_FromString(""); + } + + /* Set the flag with our string value */ + SetFlagObj(ts_str); #undef SetFlagObj #undef SetFlag return 0;