Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Disable logs by default #1383

Merged
merged 2 commits into from
Apr 24, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
18 changes: 2 additions & 16 deletions av/logging.pyi
Original file line number Diff line number Diff line change
@@ -1,5 +1,3 @@
import logging
from threading import Lock
from typing import Any, Callable

PANIC: int
Expand All @@ -13,11 +11,9 @@ TRACE: int
CRITICAL: int

def adapt_level(level: int) -> int: ...
def get_level() -> int: ...
def set_level(level: int) -> None: ...
def get_level() -> int | None: ...
def set_level(level: int | None) -> None: ...
def restore_default_callback() -> None: ...
def get_print_after_shutdown() -> bool: ...
def set_print_after_shutdown(v: bool) -> None: ...
def get_skip_repeated() -> bool: ...
def set_skip_repeated(v: bool) -> None: ...
def get_last_error() -> tuple[int, tuple[int, str, str] | None]: ...
Expand All @@ -34,13 +30,3 @@ class Capture:
value: Exception | None,
traceback: Callable[..., Any] | None,
) -> None: ...

level_threshold: int
print_after_shutdown: bool
skip_repeated: bool
skip_lock: Lock
last_log: tuple[int, str, str] | None
skip_count: int
last_error: tuple[int, str, str] | None
global_captures: list[list[tuple[int, str, str]]]
thread_captures: dict[int, list[tuple[int, str, str]]]
174 changes: 76 additions & 98 deletions av/logging.pyx
Original file line number Diff line number Diff line change
@@ -1,6 +1,21 @@
"""
FFmpeg has a logging system that it uses extensively. PyAV hooks into that system
to translate FFmpeg logs into Python's
FFmpeg has a logging system that it uses extensively. It's very noisy so PyAV turns it
off by default. This, unfortunately has the effect of making raised errors having less
detailed messages. It's therefore recommended to use VERBOSE when developing.

.. _enable_logging:

Enabling Logging
~~~~~~~~~~~~~~~~~

You can hook the logging system with Python by setting the log level::

import av

av.logging.set_level(av.logging.VERBOSE)


PyAV hooks into that system to translate FFmpeg logs into Python's
`logging system <https://docs.python.org/3/library/logging.html#logging.basicConfig>`_.

If you are not already using Python's logging system, you can initialize it
Expand All @@ -10,19 +25,12 @@ quickly with::
logging.basicConfig()


.. _disable_logging:

Disabling Logging
~~~~~~~~~~~~~~~~~

You can disable hooking the logging system with an environment variable::

export PYAV_LOGGING=off

or at runtime with :func:`restore_default_callback`.
Note that handling logs with Python sometimes doesn't play nice multi-threads workflows.
An alternative is :func:`restore_default_callback`.

This will leave (or restore) the FFmpeg logging system, which prints to the terminal.
This may also result in raised errors having less detailed messages.
This will restores FFmpeg's logging default system, which prints to the terminal.
Like with setting the log level to ``None``, this may also result in raised errors
having less detailed messages.


API Reference
Expand All @@ -37,12 +45,10 @@ from libc.stdio cimport fprintf, stderr
from libc.stdlib cimport free, malloc

import logging
import os
import sys
from threading import Lock, get_ident

# Library levels.
# QUIET = lib.AV_LOG_QUIET # -8; not really a level.
PANIC = lib.AV_LOG_PANIC # 0
FATAL = lib.AV_LOG_FATAL # 8
ERROR = lib.AV_LOG_ERROR
Expand Down Expand Up @@ -72,68 +78,52 @@ cpdef adapt_level(int level):
elif level <= lib.AV_LOG_DEBUG:
return 5 # Lower than any logging constant.
else: # lib.AV_LOG_TRACE
return 1 # ... yeah.
return 1


# While we start with the level quite low, Python defaults to INFO, and so
# they will not show. The logging system can add significant overhead, so
# be wary of dropping this lower.
cdef int level_threshold = lib.AV_LOG_VERBOSE
cdef object level_threshold = None

# ... but lets limit ourselves to WARNING (assuming nobody already did this).
if "libav" not in logging.Logger.manager.loggerDict:
logging.getLogger("libav").setLevel(logging.WARNING)


def get_level():
"""Return current FFmpeg logging threshold. See :func:`set_level`."""
"""Returns the current log level. See :func:`set_level`."""
return level_threshold


def set_level(int level):
def set_level(level):
"""set_level(level)

Sets logging threshold when converting from FFmpeg's logging system
to Python's. It is recommended to use the constants available in this
module to set the level: ``PANIC``, ``FATAL``, ``ERROR``,
``WARNING``, ``INFO``, ``VERBOSE``, and ``DEBUG``.

While less efficient, it is generally preferable to modify logging
with Python's :mod:`logging`, e.g.::
Sets PyAV's log level. It can be set to constants available in this
module: ``PANIC``, ``FATAL``, ``ERROR``, ``WARNING``, ``INFO``,
``VERBOSE``, ``DEBUG``, or ``None`` (the default).

logging.getLogger('libav').setLevel(logging.ERROR)
PyAV defaults to totally ignoring all ffmpeg logs. This has the side effect of
making certain Exceptions have no messages. It's therefore recommended to use:

PyAV defaults to translating everything except ``AV_LOG_DEBUG``, so this
function is only nessesary to use if you want to see those messages as well.
``AV_LOG_DEBUG`` will be translated to a level 5 message, which is lower
than any builtin Python logging level, so you must lower that as well::

logging.getLogger().setLevel(5)
av.logging.set_level(av.logging.VERBOSE)

When developing your application.
"""
global level_threshold
level_threshold = level

if level is None:
level_threshold = level
lib.av_log_set_callback(nolog_callback)
elif type(level) is int:
level_threshold = level
lib.av_log_set_callback(log_callback)
else:
raise ValueError("level must be: int | None")


def restore_default_callback():
"""Revert back to FFmpeg's log callback, which prints to the terminal."""
lib.av_log_set_callback(lib.av_log_default_callback)


cdef bint print_after_shutdown = False


def get_print_after_shutdown():
"""Will logging continue to ``stderr`` after Python shutdown?"""
return print_after_shutdown


def set_print_after_shutdown(v):
"""Set if logging should continue to ``stderr`` after Python shutdown."""
global print_after_shutdown
print_after_shutdown = bool(v)


cdef bint skip_repeated = True
cdef skip_lock = Lock()
cdef object last_log = None
Expand Down Expand Up @@ -226,47 +216,6 @@ cpdef log(int level, str name, str message):
free(obj)


cdef void log_callback(void *ptr, int level, const char *format, lib.va_list args) noexcept nogil:

cdef bint inited = lib.Py_IsInitialized()
if not inited and not print_after_shutdown:
return

# Fast path: avoid logging overhead. This should match the
# log_callback_gil() checks that result in ignoring the message.
with gil:
if level > level_threshold and level != lib.AV_LOG_ERROR:
return

# Format the message.
cdef char message[1024]
lib.vsnprintf(message, 1023, format, args)

# Get the name.
cdef const char *name = NULL
cdef lib.AVClass *cls = (<lib.AVClass**>ptr)[0] if ptr else NULL
if cls and cls.item_name:
# I'm not 100% on this, but this should be static, and so
# it doesn't matter if the AVClass that returned it vanishes or not.
name = cls.item_name(ptr)

if not inited:
fprintf(stderr, "av.logging (after shutdown): %s[%d]: %s\n",
name, level, message)
return

with gil:
try:
log_callback_gil(level, name, message)

except Exception as e:
fprintf(stderr, "av.logging: exception while handling %s[%d]: %s\n",
name, level, message)
# For some reason lib.PyErr_PrintEx(0) won't work.
exc, type_, tb = sys.exc_info()
lib.PyErr_Display(exc, type_, tb)


cdef log_callback_gil(int level, const char *c_name, const char *c_message):
global error_count
global skip_count
Expand Down Expand Up @@ -336,8 +285,37 @@ cdef log_callback_emit(log):
logger.log(py_level, message.strip())


# Start the magic!
# We allow the user to fully disable the logging system as it will not play
# nicely with subinterpreters due to FFmpeg-created threads.
if os.environ.get("PYAV_LOGGING") != "off":
lib.av_log_set_callback(log_callback)
cdef void log_callback(void *ptr, int level, const char *format, lib.va_list args) noexcept nogil:
cdef bint inited = lib.Py_IsInitialized()
if not inited:
return

with gil:
if level > level_threshold and level != lib.AV_LOG_ERROR:
return

# Format the message.
cdef char message[1024]
lib.vsnprintf(message, 1023, format, args)

# Get the name.
cdef const char *name = NULL
cdef lib.AVClass *cls = (<lib.AVClass**>ptr)[0] if ptr else NULL
if cls and cls.item_name:
name = cls.item_name(ptr)

with gil:
try:
log_callback_gil(level, name, message)
except Exception as e:
fprintf(stderr, "av.logging: exception while handling %s[%d]: %s\n",
name, level, message)
# For some reason lib.PyErr_PrintEx(0) won't work.
exc, type_, tb = sys.exc_info()
lib.PyErr_Display(exc, type_, tb)


cdef void nolog_callback(void *ptr, int level, const char *format, lib.va_list args) noexcept nogil:
pass

lib.av_log_set_callback(nolog_callback)
1 change: 1 addition & 0 deletions docs/index.rst
Original file line number Diff line number Diff line change
Expand Up @@ -53,6 +53,7 @@ Basic Demo

import av

av.logging.set_level(av.logging.VERBOSE)
container = av.open(path_to_video)

for index, frame in enumerate(container.decode(video=0)):
Expand Down
1 change: 1 addition & 0 deletions tests/test_colorspace.py
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@ def test_penguin_joke(self) -> None:

for packet in container.demux(stream):
for frame in packet.decode():
assert isinstance(frame, av.VideoFrame)
self.assertEqual(frame.color_range, ColorRange.JPEG) # a.k.a "pc"
self.assertEqual(frame.colorspace, Colorspace.ITU601)
return
Expand Down
14 changes: 14 additions & 0 deletions tests/test_logging.py
Original file line number Diff line number Diff line change
Expand Up @@ -22,15 +22,20 @@ def test_adapt_level(self):
)

def test_threaded_captures(self):
av.logging.set_level(av.logging.VERBOSE)

with av.logging.Capture(local=True) as logs:
do_log("main")
thread = threading.Thread(target=do_log, args=("thread",))
thread.start()
thread.join()

self.assertIn((av.logging.INFO, "test", "main"), logs)
av.logging.set_level(None)

def test_global_captures(self):
av.logging.set_level(av.logging.VERBOSE)

with av.logging.Capture(local=False) as logs:
do_log("main")
thread = threading.Thread(target=do_log, args=("thread",))
Expand All @@ -39,8 +44,11 @@ def test_global_captures(self):

self.assertIn((av.logging.INFO, "test", "main"), logs)
self.assertIn((av.logging.INFO, "test", "thread"), logs)
av.logging.set_level(None)

def test_repeats(self):
av.logging.set_level(av.logging.VERBOSE)

with av.logging.Capture() as logs:
do_log("foo")
do_log("foo")
Expand All @@ -62,7 +70,11 @@ def test_repeats(self):
],
)

av.logging.set_level(None)

def test_error(self):
av.logging.set_level(av.logging.VERBOSE)

log = (av.logging.ERROR, "test", "This is a test.")
av.logging.log(*log)
try:
Expand All @@ -71,3 +83,5 @@ def test_error(self):
self.assertEqual(e.log, log)
else:
self.fail()

av.logging.set_level(None)
4 changes: 4 additions & 0 deletions tests/test_python_io.py
Original file line number Diff line number Diff line change
Expand Up @@ -292,6 +292,8 @@ def test_writing_to_pipe_readonly(self) -> None:
)

def test_writing_to_pipe_writeonly(self):
av.logging.set_level(av.logging.VERBOSE)

buf = WriteOnlyPipe()
with self.assertRaises(ValueError) as cm:
self.write(buf)
Expand All @@ -300,6 +302,8 @@ def test_writing_to_pipe_writeonly(self):
str(cm.exception),
)

av.logging.set_level(None)

def read(self, fh, seekable: bool = True) -> None:
wrapped = MethodLogger(fh)

Expand Down
Loading