Skip to content

Commit

Permalink
Disable logs by default
Browse files Browse the repository at this point in the history
  • Loading branch information
WyattBlue committed Apr 24, 2024
1 parent defce23 commit 6806d74
Show file tree
Hide file tree
Showing 6 changed files with 93 additions and 102 deletions.
7 changes: 2 additions & 5 deletions av/logging.pyi
Original file line number Diff line number Diff line change
Expand Up @@ -13,11 +13,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 @@ -36,7 +34,6 @@ class Capture:
) -> None: ...

level_threshold: int
print_after_shutdown: bool
skip_repeated: bool
skip_lock: Lock
last_log: tuple[int, str, str] | None
Expand Down
168 changes: 71 additions & 97 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,7 +45,6 @@ from libc.stdio cimport fprintf, stderr
from libc.stdlib cimport free, malloc

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

Expand Down Expand Up @@ -72,68 +79,48 @@ 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 or type(level) is int:
level_threshold = level
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 +213,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 +282,36 @@ 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_threshold is None:
return
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)


lib.av_log_set_callback(log_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

0 comments on commit 6806d74

Please sign in to comment.