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
passstatement)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:
logfunctions.c:
main00.c:
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:
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 directlyCalling 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.
1. Log from a C .so (.dll)
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:
Output:
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.
2. Log via a Python extension module
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:
code02.py:
As a note, I couldn't reuse previous C code, so there's some duplication.
Output:
That's it!
3. Identify the bug and fix 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.
4. Conclusion
Since:
It's fixed in newer versions
There is an acceptable enough workaround for older ones
this matter can be safely closed.