Notes:
That there's already an (almost) identical question, but I wanted to give more context (and marked that one as a duplicate)
I'll be comparing log levels (probably using terms like: lower, higher, smaller, greater, decrease, increase, <, >, ...). That applies to their verbosity (amount of produced output): ERROR < WARNING < ... < INFO < ... < TRACE < ..., and NOT to their criticality (impact)
Working on a task to make logging on a complex GStreamer application consistent / uniform. One part is having GStreamer elements logs (generated by GST_* macros (expanding to GST_CAT_LEVEL_LOG, which in turn expands to a gst_debug_log call)) in Python.
That should be possible using [FreeDesktop.GStreamer]: GstInfo - Gst.debug_add_log_function (noticed the G_GNUC_NO_INSTRUMENT remark, but don't think there's anything that can be done at Python level).
Things generally work fine, although I fear that if left to run for long times (and higher log levels) some problems (memory consumption increase, even SegFaults, ...) may arise (but I'm not there yet).
But some elements run into serious problems.
Environment
Nvidia's DeepStream 6.2 container (Ubuntu 20.04.5 LTS - debugged mostly on Triton flavor, but reproducible on the others):
GStreamer 1.16.3
Python 3.8.10
PyGObject 3.36.0
NVV4L2 - version seems a bit off:
gst-inspect-1.0 video4linux2 | grep ersion Version 1.16.3 gst-inspect-1.0 nvvideo4linux2 | grep ersion Version 1.14.0
Narrowed the problem down to a MVCE: to have a pipeline that is short (both textually and also structurally (e.g.: not using bins - which have a short name but can be complex, containing a bunch of other elements)).
code00.py:
#!/usr/bin/env python
import sys
import time
import gi
gi.require_version("Gst", "1.0")
from gi.repository import GLib, Gst
pipeline_string = "videotestsrc pattern=18 ! nvvideoconvert ! nvv4l2h264enc ! fakesink sync=0"
#pipeline_string = "filesrc location=\"/opt/nvidia/deepstream/deepstream/samples/streams/sample_1080p_h264.mp4\" ! qtdemux ! h264parse ! nvv4l2decoder ! nvvideoconvert ! xvimagesink sync=0"
def log_function(
category: Gst.DebugCategory,
level: Gst.DebugLevel,
file: str,
function: str,
line: int,
obj: Gst.Object,
msg: Gst.DebugMessage,
# user_data: Any = None,
):
txt = (
f"{Gst.debug_level_get_name(level)} {category.name} - {file}:{line}:{function}:",
f"<{obj.get_name()} ({getattr(obj.__class__, '__name__')})>" if obj else "<None> ",
f"{msg.get()}"
)
print("".join(txt))
def run_pipeline():
pipeline = Gst.parse_launch(pipeline_string)
loop = GLib.MainLoop()
bus = pipeline.get_bus()
#bus.add_signal_watch()
pipeline.set_state(Gst.State.PLAYING)
start_time = time.time()
try:
loop.run()
except KeyboardInterrupt:
print("<Ctrl + C> pressed.")
except:
print(f"Funky exception caught: {sys.exc_info()[:2]}")
finally:
pipeline.set_state(Gst.State.NULL)
loop.quit()
print(f"--- Ran for {time.time() - start_time:.3f} seconds")
def main(*argv):
custom_log = bool(argv) # Custom log if any argument passed
print(f"---\nCustom log function: {custom_log}\nRunning pipeline:\n gst-launch-1.0 -e {pipeline_string}\n---\n")
Gst.init(None)
if custom_log:
Gst.debug_remove_log_function()
Gst.debug_add_log_function(log_function)
run_pipeline()
if __name__ == "__main__":
print("Python {:s} {:03d}bit on {:s}\n".format(" ".join(elem.strip() for elem in sys.version.split("\n")),
64 if sys.maxsize > 0x100000000 else 32, sys.platform))
rc = main(*sys.argv[1:])
print("\nDone.\n")
sys.exit(rc)
Some may argue that code is not complete (no callback to monitor messages on the bus), but I wanted to keep it simple (and I don't care if when playing a video, at the end pipeline doesn't quit - I interrupt it by pressing Ctrl + C anyway). Just to be explicit, I did try with a complete version, but same results.
Output:
[root@cfati-5510-0:~/Work/Dev/StackExchange/StackOverflow/q077932526]> . ~/sopr.sh ### Set shorter prompt to better fit when pasted in StackOverflow (or other) pages ### [064bit prompt]> [064bit prompt]> ls code00.py [064bit prompt]> [064bit prompt]> # ---------- DEFAULT LOG ---------- [064bit prompt]> GST_DEBUG=2 python ./code00.py Python 3.8.10 (default, Jun 22 2022, 20:18:18) [GCC 9.4.0] 064bit on linux --- Custom log function: False Running pipeline: gst-launch-1.0 -e videotestsrc pattern=18 ! nvvideoconvert ! nvv4l2h264enc ! fakesink sync=0 --- 0:00:00.038000133 2604541 0x1385550 WARN v4l2 gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<nvv4l2h264enc0:sink> Unable to try format: Unknown error -1 0:00:00.038029358 2604541 0x1385550 WARN v4l2 gstv4l2object.c:2942:gst_v4l2_object_probe_caps_for_format:<nvv4l2h264enc0:sink> Could not probe minimum capture size for pixelformat YM12 0:00:00.038046357 2604541 0x1385550 WARN v4l2 gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<nvv4l2h264enc0:sink> Unable to try format: Unknown error -1 0:00:00.038061061 2604541 0x1385550 WARN v4l2 gstv4l2object.c:2948:gst_v4l2_object_probe_caps_for_format:<nvv4l2h264enc0:sink> Could not probe maximum capture size for pixelformat YM12 0:00:00.038080317 2604541 0x1385550 WARN v4l2 gstv4l2object.c:2395:gst_v4l2_object_add_interlace_mode:0x13873f0 Failed to determine interlace mode 0:00:00.038109676 2604541 0x1385550 WARN v4l2 gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<nvv4l2h264enc0:sink> Unable to try format: Unknown error -1 0:00:00.038123283 2604541 0x1385550 WARN v4l2 gstv4l2object.c:2942:gst_v4l2_object_probe_caps_for_format:<nvv4l2h264enc0:sink> Could not probe minimum capture size for pixelformat NM12 0:00:00.038134452 2604541 0x1385550 WARN v4l2 gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<nvv4l2h264enc0:sink> Unable to try format: Unknown error -1 0:00:00.038148304 2604541 0x1385550 WARN v4l2 gstv4l2object.c:2948:gst_v4l2_object_probe_caps_for_format:<nvv4l2h264enc0:sink> Could not probe maximum capture size for pixelformat NM12 0:00:00.038161000 2604541 0x1385550 WARN v4l2 gstv4l2object.c:2395:gst_v4l2_object_add_interlace_mode:0x13873f0 Failed to determine interlace mode 0:00:00.038243374 2604541 0x1385550 WARN v4l2 gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<nvv4l2h264enc0:src> Unable to try format: Unknown error -1 0:00:00.038262117 2604541 0x1385550 WARN v4l2 gstv4l2object.c:2942:gst_v4l2_object_probe_caps_for_format:<nvv4l2h264enc0:src> Could not probe minimum capture size for pixelformat H264 0:00:00.038276388 2604541 0x1385550 WARN v4l2 gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<nvv4l2h264enc0:src> Unable to try format: Unknown error -1 0:00:00.038289047 2604541 0x1385550 WARN v4l2 gstv4l2object.c:2948:gst_v4l2_object_probe_caps_for_format:<nvv4l2h264enc0:src> Could not probe maximum capture size for pixelformat H264 0:00:00.098620457 2604541 0x107bde0 WARN v4l2bufferpool gstv4l2bufferpool.c:1082:gst_v4l2_buffer_pool_start:<nvv4l2h264enc0:pool:src> Uncertain or not enough buffers, enabling copy threshold 0:00:00.103610735 2604541 0x1399060 WARN v4l2bufferpool gstv4l2bufferpool.c:1533:gst_v4l2_buffer_pool_dqbuf:<nvv4l2h264enc0:pool:src> Driver should never set v4l2_buffer.field to ANY ^C<Ctrl + C> pressed. --- Ran for 4.508 seconds Done. [064bit prompt]> [064bit prompt]> # ---------- CUSTOM LOG ---------- [064bit prompt]> GST_DEBUG=2 python ./code00.py 1 Python 3.8.10 (default, Jun 22 2022, 20:18:18) [GCC 9.4.0] 064bit on linux --- Custom log function: True Running pipeline: gst-launch-1.0 -e videotestsrc pattern=18 ! nvvideoconvert ! nvv4l2h264enc ! fakesink sync=0 --- WARN v4l2 - gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<sink (Pad)>Unable to try format: Unknown error -1 WARN v4l2 - gstv4l2object.c:2942:gst_v4l2_object_probe_caps_for_format:<sink (Pad)>Could not probe minimum capture size for pixelformat YM12 WARN v4l2 - gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<sink (Pad)>Unable to try format: Unknown error -1 WARN v4l2 - gstv4l2object.c:2948:gst_v4l2_object_probe_caps_for_format:<sink (Pad)>Could not probe maximum capture size for pixelformat YM12 code00.py:44: Warning: g_object_is_floating: assertion 'G_IS_OBJECT (object)' failed pipeline.set_state(Gst.State.PLAYING) code00.py:44: Warning: g_object_get_qdata: assertion 'G_IS_OBJECT (object)' failed pipeline.set_state(Gst.State.PLAYING) Segmentation fault (core dumped)
Notes:
Error is reproducible for any of the 3 coders in the NVV4L2 plugin
Looking at the above differences, the 1st line that appears in the good run after the last one seen in the crashed one is: v4l2 gstv4l2object.c:2395:gst_v4l2_object_add_interlace_mode:0x13873f0 Failed to determine interlace mode (this happens every time)
Works fine when decreasing the log level (ERROR, 1), but then it's pretty much useless (log wise)
Based on the observations above, one can conclude that the error has something to do with that particular line. Worth mentioning that I browsed several Gst-Plugins-Good versions (gst-plugins-good/sys/v4l2/gstv4l2object.c) but none of them has the exact line numbers (those particular lines of code don't seem to change though).
Also noted that error occurs even for:
Dummy log functions (containing just a pass statement)
Extension modules (I created one with a (dummy) log function)
References:
[SO]: Collecting GStreamer logs in Python ends with Segmentation fault
[FreeDesktop.GitLab]: [BUG] Collecting GStreamer logs in Python ends with Segmentation fault (referenced by previous)
[SO]: Redirecting Gstreamer logs in python from stdout/stderr to a custom logging handler
[Nvidia.Developer.Forums]: NVIDIA gstreamer element segfaults with `Gst.debug_add_log_function` race condition (referenced by previous)
[Nvidia.Developer.Forums]: Deepstream h265parser segfaults with gstreamer gst_debug_add_log_function
On a closing note, marshaling the GStreamer objects to Python will have a negative impact on performance (especially if happening often during pipeline run).
Note: Posting an answer, although it doesn't identify and fix the problem (not yet, at least).
It's more like a debugging log (and possible ways to work around it).
The next logical step (for me) was to try replicating the behavior from C (get rid of Python layer). Due to some comments in the 1st and 2nd references (from the question), indicating a GStreamer bug (the behavior no longer being reproducible with v1.20), I was kind of expecting similar results.
logfunctions.h:
#pragma once
#include <gst/gst.h>
typedef enum {
Data = 1,
} LogFunctionInfo;
#if defined(__cplusplus)
extern "C" {
#endif
void addLogFunction(LogFunctionInfo info, int removeDefault);
void clearLogFunction(LogFunctionInfo info, int addDefault);
#if defined(__cplusplus)
}
#endif
logfunctions.c:
#include <gst/gst.h>
#include "logfunctions.h"
static G_GNUC_NO_INSTRUMENT
void logFunctionData(
GstDebugCategory *category,
GstDebugLevel level,
const gchar *file,
const gchar *function,
gint line,
GObject *object,
GstDebugMessage *message,
gpointer user_data
)
{
g_print(
"%s %s - %s:%d:%s:<%p (%s)> %s\n",
gst_debug_level_get_name(level), category->name, file, line, function, object,
#if defined(NO_OBJECT_CHECK)
G_OBJECT_TYPE_NAME(object),
#else
G_IS_OBJECT(object) ? G_OBJECT_TYPE_NAME(object) : "",
#endif
gst_debug_message_get(message)
);
}
static GstLogFunction logFunction(LogFunctionInfo info)
{
switch (info) {
case Data:
return logFunctionData;
default:
return NULL;
}
}
void addLogFunction(LogFunctionInfo info, int removeDefault)
{
if (removeDefault) {
gst_debug_remove_log_function(NULL);
}
GstLogFunction logFunc = logFunction(info);
if (logFunc) {
gst_debug_add_log_function(logFunc, NULL, NULL);
}
}
void clearLogFunction(LogFunctionInfo info, int addDefault)
{
GstLogFunction logFunc = logFunction(info);
if (logFunc) {
gst_debug_remove_log_function(logFunc);
}
if (addDefault) {
gst_debug_add_log_function(NULL, NULL, NULL);
}
}
main00.c:
#include <stdio.h>
#include <time.h>
#include <gst/gst.h>
#include "logfunctions.c" // logFunctionData is required
#define PIPE_FAIL "videotestsrc pattern=18 ! nvvideoconvert ! nvv4l2h264enc ! fakesink sync=0"
//#define PIPE_FAIL "filesrc location=\"/opt/nvidia/deepstream/deepstream/samples/streams/sample_1080p_h264.mp4\" ! qtdemux ! h264parse ! nvv4l2decoder ! nvvideoconvert ! xvimagesink sync=0"
static /*volatile*/ GstElement *pipeline = NULL;
void signalHandler(int sig)
{
if (pipeline) {
gst_element_send_event(pipeline, gst_event_new_eos());
}
}
int main(int argc, char **argv)
{
char pipeline_string[] = PIPE_FAIL;
g_print("---\nCustom log function: %s\nRunning pipeline:\n gst-launch-1.0 -e %s\n---\n",
(argc > 1) ? "True" : "False", pipeline_string
);
gst_init(NULL, NULL);
if (argc > 1) {
g_print("Adding log function\n");
gst_debug_remove_log_function(NULL);
gst_debug_add_log_function(logFunctionData, NULL, NULL);
}
GError *error = NULL;
pipeline = gst_parse_launch(pipeline_string, &error);
if (!pipeline) {
g_print("Parse error: %s\n", error->message);
return -3;
}
struct sigaction act;
act.sa_handler = signalHandler;
sigaction(SIGINT, &act, NULL);
clock_t timeStart = clock();
gst_element_set_state(pipeline, GST_STATE_PLAYING);
GstBus *bus = gst_element_get_bus(pipeline);
GstMessage *msg = gst_bus_poll(bus, GST_MESSAGE_EOS | GST_MESSAGE_ERROR, -1);
switch (GST_MESSAGE_TYPE(msg)) {
case GST_MESSAGE_EOS: {
g_print("EOS\n");
break;
}
case GST_MESSAGE_ERROR: {
GError *err = NULL;
gchar *dbg = NULL;
gst_message_parse_error(msg, &err, &dbg);
if (err) {
g_printerr("ERROR: %s\n", err->message);
g_error_free(err);
}
if (dbg) {
g_printerr("[Debug details: %s]\n", dbg);
g_free(dbg);
}
}
default:
g_printerr("Unexpected message of type %d", GST_MESSAGE_TYPE(msg));
break;
}
g_print("--- Ran for %.3f seconds\n", ((double)clock() - timeStart) / CLOCKS_PER_SEC);
gst_message_unref(msg);
gst_element_set_state(pipeline, GST_STATE_NULL);
gst_object_unref(bus);
gst_object_unref(pipeline);
gst_deinit();
g_print("\nDone.\n\n");
return 0;
}
Notes:
Pedantic coders might argue about some "unorthodox" things in the code, but again, it's just for simplicity and don't have any (negative) functional effect
Code is way too complex for now, but this structuring will come in handy at a later stage
Output:
[root@cfati-5510-0:~/Work/Dev/StackExchange/StackOverflow/q077932526]> . ~/sopr.sh ### Set shorter prompt to better fit when pasted in StackOverflow (or other) pages ### [064bit prompt]> [064bit prompt]> ls code00.py logfunctions.c logfunctions.h main00.c [064bit prompt]> gcc -Wall -g -O2 -fPIC -DPIC -pthread -I/usr/include/gstreamer-1.0 -I/usr/include/glib-2.0 -I/usr/lib/x86_64-linux-gnu/glib-2.0/include -Wl,-no-undefined -o ./main00 ./main00.c -lgstreamer-1.0 -lgobject-2.0 -lglib-2.0 [064bit prompt]> ls code00.py logfunctions.c logfunctions.h main00 main00.c [064bit prompt]> [064bit prompt]> # ---------- DEFAULT LOG ---------- [064bit prompt]> GST_DEBUG=2 ./main00 --- Custom log function: False Running pipeline: gst-launch-1.0 -e videotestsrc pattern=18 ! nvvideoconvert ! nvv4l2h264enc ! fakesink sync=0 --- 0:00:00.043512822 2624802 0x55bf01c8d810 WARN v4l2 gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<nvv4l2h264enc0:sink> Unable to try format: Unknown error -1 0:00:00.043537781 2624802 0x55bf01c8d810 WARN v4l2 gstv4l2object.c:2942:gst_v4l2_object_probe_caps_for_format:<nvv4l2h264enc0:sink> Could not probe minimum capture size for pixelformat YM12 0:00:00.043547295 2624802 0x55bf01c8d810 WARN v4l2 gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<nvv4l2h264enc0:sink> Unable to try format: Unknown error -1 0:00:00.043555280 2624802 0x55bf01c8d810 WARN v4l2 gstv4l2object.c:2948:gst_v4l2_object_probe_caps_for_format:<nvv4l2h264enc0:sink> Could not probe maximum capture size for pixelformat YM12 0:00:00.043565126 2624802 0x55bf01c8d810 WARN v4l2 gstv4l2object.c:2395:gst_v4l2_object_add_interlace_mode:0x55bf01c81df0 Failed to determine interlace mode # @TODO - cfati: Truncated output 0:00:00.104239660 2624802 0x55bf01930b00 WARN v4l2bufferpool gstv4l2bufferpool.c:1082:gst_v4l2_buffer_pool_start:<nvv4l2h264enc0:pool:src> Uncertain or not enough buffers, enabling copy threshold 0:00:00.109120156 2624802 0x55bf01c91980 WARN v4l2bufferpool gstv4l2bufferpool.c:1533:gst_v4l2_buffer_pool_dqbuf:<nvv4l2h264enc0:pool:src> Driver should never set v4l2_buffer.field to ANY ^C0:00:03.420535632 2624802 0x55bf01c91980 WARN v4l2allocator gstv4l2allocator.c:1510:gst_v4l2_allocator_dqbuf:<nvv4l2h264enc0:pool:src:allocator> V4L2 provided buffer has bytesused 0 which is too small to include > data_offset 0 EOS --- Ran for 4.103 seconds Done. [064bit prompt]> [064bit prompt]> # ---------- CUSTOM LOG ---------- [064bit prompt]> GST_DEBUG=2 ./main00 1 --- Custom log function: True Running pipeline: gst-launch-1.0 -e videotestsrc pattern=18 ! nvvideoconvert ! nvv4l2h264enc ! fakesink sync=0 --- Adding log function WARN v4l2 - gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<0x5650b754e7f0 (GstPad)> Unable to try format: Unknown error -1 WARN v4l2 - gstv4l2object.c:2942:gst_v4l2_object_probe_caps_for_format:<0x5650b754e7f0 (GstPad)> Could not probe minimum capture size for pixelformat YM12 WARN v4l2 - gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<0x5650b754e7f0 (GstPad)> Unable to try format: Unknown error -1 WARN v4l2 - gstv4l2object.c:2948:gst_v4l2_object_probe_caps_for_format:<0x5650b754e7f0 (GstPad)> Could not probe maximum capture size for pixelformat YM12 WARN v4l2 - gstv4l2object.c:2395:gst_v4l2_object_add_interlace_mode:<0x5650b763f800 ((null))> Failed to determine interlace mode # @TODO - cfati: Truncated output WARN v4l2bufferpool - gstv4l2bufferpool.c:1082:gst_v4l2_buffer_pool_start:<0x7f40d0010350 (GstNvV4l2BufferPool)> Uncertain or not enough buffers, enabling copy threshold WARN v4l2bufferpool - gstv4l2bufferpool.c:1533:gst_v4l2_buffer_pool_dqbuf:<0x7f40d0010350 (GstNvV4l2BufferPool)> Driver should never set v4l2_buffer.field to ANY ^CEOS --- Ran for 3.482 seconds Done.
So, it worked.
I know it's too soon, and I don't want to point any fingers as there's a lot of info that I'm missing, but I can't help not thinking about PyGObject. A couple of more things that I found about it during investigations:
Running a simple pipeline containing a sink bin: videotestsrc ! autovideosink sync=0 (noticed for AutoVideoSink, FPSDisplaySink) and a level higher than FIXME (3) triggers an assertion error (and SegFault or program freezing). This is one of the reasons why I use XVImageSink directly
Calling log functions fails before Gst.init (which sucks as things are being logged during initialization). But discovered (by dumb luck) that for newer versions (tried with v3.46.2) this restriction goes away. It was just a coincidence, I tried on another environment and v3.36.0 works. So, this behavior is due to other factors like: environment variables, dependents (maybe GIR (gir1.2-glib-2.0)), ...
So I'm trying to move away from it. But there's no straightforward way. Thought about a couple of workarounds.
Steps:
Create a .dll containing:
A logging (callback) function mirroring the one from Python. Of course, easier to say than done. If it only formats the info and spits it to StdOut, then it's OK, but if it's doing more than that (e.g.: using loggers or other Python stuff) then this is a dead end
Another function adding the previous one to the GStreamer logging system. Optionally, its counterpart
Use the .dll (#1.2.) from Python via CTypes (check [SO]: C function called from Python via ctypes returns incorrect value (@CristiFati's answer) for a common pitfall)
Now, the (above) code structure starts to make sense.
code01.py:
#!/usr/bin/env python
import ctypes as cts
import sys
import time
import gi
from code00 import pipeline_string, run_pipeline
gi.require_version("Gst", "1.0")
from gi.repository import Gst
def main(*argv):
log_func_info = int(argv[0]) if argv and argv[0].isdecimal() else 0
print(f"---\nCustom log function info: {log_func_info}\nRunning pipeline:\n gst-launch-1.0 -e {pipeline_string}\n---\n")
if log_func_info:
log_dll = cts.CDLL("liblogfunctions.so")
add_log_function = log_dll.addLogFunction
add_log_function.argtypes = (cts.c_int, cts.c_int)
add_log_function.restype = None
# @TODO - cfati: Same thing for clearLogFunction
add_log_function(log_func_info, 1)
Gst.init(None)
run_pipeline()
if __name__ == "__main__":
print("Python {:s} {:03d}bit on {:s}\n".format(" ".join(elem.strip() for elem in sys.version.split("\n")),
64 if sys.maxsize > 0x100000000 else 32, sys.platform))
rc = main(*sys.argv[1:])
print("\nDone.\n")
sys.exit(rc)
Output:
[064bit prompt]> ls code00.py code01.py logfunctions.c logfunctions.h main00 main00.c [064bit prompt]> gcc -Wall -g -O2 -fPIC -DPIC -pthread -I/usr/include/gstreamer-1.0 -I/usr/include/glib-2.0 -I/usr/lib/x86_64-linux-gnu/glib-2.0/include -Wl,-no-undefined -shared -o ./liblogfunctions.so ./logfunctions.c -lgstreamer-1.0 -lgobject-2.0 -lglib-2.0 [064bit prompt]> ls code00.py code01.py liblogfunctions.so logfunctions.c logfunctions.h main00 main00.c [064bit prompt]> [064bit prompt]> # ---------- DEFAULT LOG ---------- [064bit prompt]> GST_DEBUG=2 LD_LIBRARY_PATH="${LD_LIBRARY_PATH}:$(pwd)" python ./code01.py Python 3.8.10 (default, Jun 22 2022, 20:18:18) [GCC 9.4.0] 064bit on linux --- Custom log function info: 0 Running pipeline: gst-launch-1.0 -e videotestsrc pattern=18 ! nvvideoconvert ! nvv4l2h264enc ! fakesink sync=0 --- 0:00:00.034999454 2640153 0x11a8f50 WARN v4l2 gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<nvv4l2h264enc0:sink> Unable to try format: Unknown error -1 0:00:00.035022095 2640153 0x11a8f50 WARN v4l2 gstv4l2object.c:2942:gst_v4l2_object_probe_caps_for_format:<nvv4l2h264enc0:sink> Could not probe minimum capture size for pixelformat YM12 0:00:00.035029968 2640153 0x11a8f50 WARN v4l2 gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<nvv4l2h264enc0:sink> Unable to try format: Unknown error -1 0:00:00.035036390 2640153 0x11a8f50 WARN v4l2 gstv4l2object.c:2948:gst_v4l2_object_probe_caps_for_format:<nvv4l2h264enc0:sink> Could not probe maximum capture size for pixelformat YM12 0:00:00.035045428 2640153 0x11a8f50 WARN v4l2 gstv4l2object.c:2395:gst_v4l2_object_add_interlace_mode:0x11aac60 Failed to determine interlace mode # @TODO - cfati: Truncated output 0:00:00.095513670 2640153 0xea2de0 WARN v4l2bufferpool gstv4l2bufferpool.c:1082:gst_v4l2_buffer_pool_start:<nvv4l2h264enc0:pool:src> Uncertain or not enough buffers, enabling copy threshold 0:00:00.100683366 2640153 0x11bc060 WARN v4l2bufferpool gstv4l2bufferpool.c:1533:gst_v4l2_buffer_pool_dqbuf:<nvv4l2h264enc0:pool:src> Driver should never set v4l2_buffer.field to ANY ^C<Ctrl + C> pressed. --- Ran for 2.284 seconds Done. [064bit prompt]> [064bit prompt]> # ---------- CUSTOM LOG ---------- [064bit prompt]> GST_DEBUG=2 LD_LIBRARY_PATH="${LD_LIBRARY_PATH}:$(pwd)" python ./code01.py 1 Python 3.8.10 (default, Jun 22 2022, 20:18:18) [GCC 9.4.0] 064bit on linux --- Custom log function info: 1 Running pipeline: gst-launch-1.0 -e videotestsrc pattern=18 ! nvvideoconvert ! nvv4l2h264enc ! fakesink sync=0 --- WARN v4l2 - gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<0x1c2a7d0 (GstPad)> Unable to try format: Unknown error -1 WARN v4l2 - gstv4l2object.c:2942:gst_v4l2_object_probe_caps_for_format:<0x1c2a7d0 (GstPad)> Could not probe minimum capture size for pixelformat YM12 WARN v4l2 - gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<0x1c2a7d0 (GstPad)> Unable to try format: Unknown error -1 WARN v4l2 - gstv4l2object.c:2948:gst_v4l2_object_probe_caps_for_format:<0x1c2a7d0 (GstPad)> Could not probe maximum capture size for pixelformat YM12 WARN v4l2 - gstv4l2object.c:2395:gst_v4l2_object_add_interlace_mode:<0x1d1b060 ((null))> Failed to determine interlace mode # @TODO - cfati: Truncated output WARN v4l2bufferpool - gstv4l2bufferpool.c:1082:gst_v4l2_buffer_pool_start:<0x7f7700010090 (GstNvV4l2BufferPool)> Uncertain or not enough buffers, enabling copy threshold WARN v4l2bufferpool - gstv4l2bufferpool.c:1533:gst_v4l2_buffer_pool_dqbuf:<0x7f7700010090 (GstNvV4l2BufferPool)> Driver should never set v4l2_buffer.field to ANY ^C<Ctrl + C> pressed. --- Ran for 3.394 seconds Done. [064bit prompt]> [064bit prompt]> # ---------- CUSTOM (NO) LOG ---------- [064bit prompt]> GST_DEBUG=2 LD_LIBRARY_PATH="${LD_LIBRARY_PATH}:$(pwd)" python ./code01.py 2 Python 3.8.10 (default, Jun 22 2022, 20:18:18) [GCC 9.4.0] 064bit on linux --- Custom log function info: 2 Running pipeline: gst-launch-1.0 -e videotestsrc pattern=18 ! nvvideoconvert ! nvv4l2h264enc ! fakesink sync=0 --- ^C<Ctrl + C> pressed. --- Ran for 2.515 seconds Done.
Bingo !!!
I let it run for a couple of minutes with a greater level (DEBUG, 5) and it performed fine. By no means I conclude that it passed the time test (must check how it behaves when running for days), but definitely it's a start.
It's a more elaborate form of the previous, with a couple of key differences:
Functionally: The function adding the log callback will need to receive another argument, and that is the Python function that the callback will have to call. So, the information from GStreamer objects will be extracted by the callback (after all, text is being logged, not objects), and will be passed to the Python function (via [Python.Docs]: Python/C API Reference Manual) as plain Python objects, thus bypassing PyGObject
Structurally: It's a "special" .dll following Python module protocol ([Python.Docs]: Extending and Embedding the Python Interpreter). I don't think it's mandatory to be so (can be a regular .dll), but CTypes can be confusing for some users (with no low level background), and also a bunch of conversions are automatically performed. The drawback is that (C) boilerplate code needs to be written
Code:
gstlogmodule.c:
#define PY_SSIZE_T_CLEAN
#include <Python.h>
#include <gst/gst.h>
#define FUNC_NAME "python"
static PyObject *gPythonFunc = NULL;
static G_GNUC_NO_INSTRUMENT
void logFunction(
GstDebugCategory *category,
GstDebugLevel level,
const gchar *file,
const gchar *function,
gint line,
GObject *object,
GstDebugMessage *message,
gpointer user_data
)
{
if (gPythonFunc == NULL) {
//g_print("Would output too much garbage\n");
return;
}
if (_Py_IsFinalizing()) {
return;
}
PyGILState_STATE gstate = PyGILState_Ensure();
if (!PyObject_CallFunction(
gPythonFunc, "sssis(Ks)s",
gst_debug_level_get_name(level), category->name,
file, line, function, (uintptr_t)object,
G_IS_OBJECT(object) ? G_OBJECT_TYPE_NAME(object) : "",
gst_debug_message_get(message)
)) {
g_print("PyObject_CallFunction\n");
PyErr_Clear();
}
PyGILState_Release(gstate);
}
static void clear()
{
gst_debug_remove_log_function(logFunction);
Py_XDECREF(gPythonFunc);
gPythonFunc = NULL;
}
static PyObject* pySetLogFunction(PyObject *self, PyObject *args)
{
char *info = NULL;
int removeDefault = 0;
PyObject *pythonFunc = NULL;
if(!PyArg_ParseTuple(args, "siO", &info, &removeDefault, &pythonFunc)) {
return NULL;
}
if (!PyCallable_Check(pythonFunc)) {
PyErr_SetString(PyExc_ValueError, "Invalid Python function (callable)");
return NULL;
}
if (removeDefault) {
gst_debug_remove_log_function(NULL);
}
if (!strcmp(info, FUNC_NAME)) {
clear();
Py_INCREF(pythonFunc);
gPythonFunc = pythonFunc;
gst_debug_add_log_function(logFunction, NULL, NULL);
}
Py_RETURN_NONE;
}
static PyObject* pyClearLogFunction(PyObject *self, PyObject *args)
{
char *info = NULL;
int addDefault = 0;
if(!PyArg_ParseTuple(args, "si", &info, &addDefault)) {
return NULL;
}
if ((gPythonFunc != NULL) && (!strcmp(info, FUNC_NAME))) {
clear();
}
if (addDefault) {
gst_debug_add_log_function(NULL, NULL, NULL);
}
Py_RETURN_NONE;
}
static PyMethodDef gstLogMethods[] = {
{ "set_log_function", pySetLogFunction, METH_VARARGS, "Set log function" },
{ "clear_log_function", pyClearLogFunction, METH_VARARGS, "Clear log function" },
{ NULL, NULL, 0, NULL }
};
static struct PyModuleDef gstLogModule = {
PyModuleDef_HEAD_INIT, "gstlog", "GStreamer logging attempt (https://stackoverflow.com/a/77933740/4788546)", -1, gstLogMethods
};
PyMODINIT_FUNC
PyInit_gstlog()
{
Py_AtExit(clear);
return PyModule_Create(&gstLogModule);
}
code02.py:
#!/usr/bin/env python
import sys
import time
from typing import Tuple
import gi
import gstlog
from code00 import pipeline_string, run_pipeline
gi.require_version("Gst", "1.0")
from gi.repository import Gst
def log_function(category: str, level: str,
file: str, line: int, function: str,
obj_data: Tuple[int, str], message: str):
print(f"PY {level} {category} - {file}:{line}:{function}:"
f"<0x{obj_data[0]:x} ({obj_data[1]})> {message}")
def main(*argv):
custom_log = bool(argv) # Custom log if any argument passed
print(f"---\nCustom log function: {custom_log}\nRunning pipeline:\n gst-launch-1.0 -e {pipeline_string}\n---\n")
if custom_log:
gstlog.set_log_function("python", 1, log_function)
Gst.init(None)
run_pipeline()
if __name__ == "__main__":
print("Python {:s} {:03d}bit on {:s}\n".format(" ".join(elem.strip() for elem in sys.version.split("\n")),
64 if sys.maxsize > 0x100000000 else 32, sys.platform))
rc = main(*sys.argv[1:])
print("\nDone.\n")
sys.exit(rc)
As a note, I couldn't reuse previous C code, so there's some duplication.
Output:
[064bit prompt]> ls code00.py code01.py code02.py gstlogmodule.c liblogfunctions.so logfunctions.c logfunctions.h main00 main00.c [064bit prompt]> gcc -Wall -g -O2 -fPIC -DPIC -pthread -I/usr/include/gstreamer-1.0 -I/usr/include/glib-2.0 -I/usr/lib/x86_64-linux-gnu/glib-2.0/include -I/usr/include/python3.8 -Wl,-no-undefined -shared -o ./gstlog.cpython-38-x86_64-linux-gnu.so ./gstlogmodule.c -lgstreamer-1.0 -lgobject-2.0 -lglib-2.0 -lpython3.8 [064bit prompt]> ls code00.py code01.py code02.py gstlog.cpython-38-x86_64-linux-gnu.so gstlogmodule.c liblogfunctions.so logfunctions.c logfunctions.h main00 main00.c [064bit prompt]> [064bit prompt]> # ---------- DEFAULT LOG ---------- [064bit prompt]> GST_DEBUG=2 python ./code02.py Python 3.8.10 (default, Jun 22 2022, 20:18:18) [GCC 9.4.0] 064bit on linux --- Custom log function: False Running pipeline: gst-launch-1.0 -e videotestsrc pattern=18 ! nvvideoconvert ! nvv4l2h264enc ! fakesink sync=0 --- 0:00:00.034991772 2679991 0x1726d50 WARN v4l2 gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<nvv4l2h264enc0:sink> Unable to try format: Unknown error -1 0:00:00.035011669 2679991 0x1726d50 WARN v4l2 gstv4l2object.c:2942:gst_v4l2_object_probe_caps_for_format:<nvv4l2h264enc0:sink> Could not probe minimum capture size for pixelformat YM12 0:00:00.035018896 2679991 0x1726d50 WARN v4l2 gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<nvv4l2h264enc0:sink> Unable to try format: Unknown error -1 0:00:00.035025451 2679991 0x1726d50 WARN v4l2 gstv4l2object.c:2948:gst_v4l2_object_probe_caps_for_format:<nvv4l2h264enc0:sink> Could not probe maximum capture size for pixelformat YM12 0:00:00.035032820 2679991 0x1726d50 WARN v4l2 gstv4l2object.c:2395:gst_v4l2_object_add_interlace_mode:0x1729cf0 Failed to determine interlace mode # @TODO - cfati: Truncated output 0:00:00.095393439 2679991 0x14201e0 WARN v4l2bufferpool gstv4l2bufferpool.c:1082:gst_v4l2_buffer_pool_start:<nvv4l2h264enc0:pool:src> Uncertain or not enough buffers, enabling copy threshold 0:00:00.100478795 2679991 0x173a460 WARN v4l2bufferpool gstv4l2bufferpool.c:1533:gst_v4l2_buffer_pool_dqbuf:<nvv4l2h264enc0:pool:src> Driver should never set v4l2_buffer.field to ANY ^C<Ctrl + C> pressed. --- Ran for 2.205 seconds Done. [064bit prompt]> [064bit prompt]> # ---------- CUSTOM LOG ---------- [064bit prompt]> GST_DEBUG=2 python ./code02.py 1 Python 3.8.10 (default, Jun 22 2022, 20:18:18) [GCC 9.4.0] 064bit on linux --- Custom log function: True Running pipeline: gst-launch-1.0 -e videotestsrc pattern=18 ! nvvideoconvert ! nvv4l2h264enc ! fakesink sync=0 --- PY v4l2 WARN - gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<0x27027d0 (GstPad)> Unable to try format: Unknown error -1 PY v4l2 WARN - gstv4l2object.c:2942:gst_v4l2_object_probe_caps_for_format:<0x27027d0 (GstPad)> Could not probe minimum capture size for pixelformat YM12 PY v4l2 WARN - gstv4l2object.c:3057:gst_v4l2_object_get_nearest_size:<0x27027d0 (GstPad)> Unable to try format: Unknown error -1 PY v4l2 WARN - gstv4l2object.c:2948:gst_v4l2_object_probe_caps_for_format:<0x27027d0 (GstPad)> Could not probe maximum capture size for pixelformat YM12 PY v4l2 WARN - gstv4l2object.c:2395:gst_v4l2_object_add_interlace_mode:<0x27f44f0 (None)> Failed to determine interlace mode # @TODO - cfati: Truncated output PY v4l2bufferpool WARN - gstv4l2bufferpool.c:1082:gst_v4l2_buffer_pool_start:<0x7fb6fc010090 (GstNvV4l2BufferPool)> Uncertain or not enough buffers, enabling copy threshold PY v4l2bufferpool WARN - gstv4l2bufferpool.c:1533:gst_v4l2_buffer_pool_dqbuf:<0x7fb6fc010090 (GstNvV4l2BufferPool)> Driver should never set v4l2_buffer.field to ANY ^C<Ctrl + C> pressed. --- Ran for 3.423 seconds Done.
That's it! 👍
The above variant(s), simply work around the actual problem (wherever it might be).
The right way would be to identify and fix it, but that seems a task for Sisyphus, and besides it's no longer reproducible in newer versions (GStreamer 1.20 from Nvidia's DeepStream 6.4) as stated in [FreeDesktop.GitLab]: GStreamer/GStreamer - Collecting GStreamer logs in Python ends with Segmentation fault.
Since:
It's fixed in newer versions
There is an acceptable enough workaround for older ones
this matter can be safely closed.