"Camera capture timed out." when setting pipeline from GST_STATE_NULL to GST_STATE_PLAYING for the second time
TimSchneider42 opened this issue · 6 comments
TimSchneider42 commented
Hey,
I have a little project where I use a Raspberry Pi as a surveillance camera. In order to save some energy (as the Pi is powered from a powerbank) I use a motion sensor to disable the IR LED and stop querying the camera whenever there is no motion in the area.
Since constructing my pipeline takes a lot of time (~1s), I only construct it once in the beginning and set it to GST_STATE_NULL while I am not using it. On my desktop PC, I use the following pipeline:
v4l2src device=/dev/video0 ! videoconvert ! x264enc ! h264parse ! splitmuxsink [...]
and everything works fine.
On my Pi on the other hand I use
rpicamsrc bitrate=1000000 ! h264parse ! splitmuxsink [...]
which works fine the first time I start the pipeline, but yields the following error on the second time:
Error received from element raspicam: Camera capture timed out.
Debugging information: gstrpicamsrc.c(1445): gst_rpi_cam_src_create (): /GstPipeline:raspiwatch-pipeline/GstRpiCamSrc:raspicam:
Waiting for a buffer from the camera took too long.
Error received from element raspicam: Camera capture timed out.
Debugging information: gstrpicamsrc.c(1445): gst_rpi_cam_src_create (): /GstPipeline:raspiwatch-pipeline/GstRpiCamSrc:raspicam:
Waiting for a buffer from the camera took too long.
Error received from element raspicam: Internal data stream error.
**
ERROR:gstsplitmuxsink.c:1380:handle_gathered_gop: assertion failed: (queued_gop_time >= 0)
An example that reproduces the problem can be found here: https://pastebin.com/ZvYpbeyj and the full debug output of that example here: https://pastebin.com/XET7ZyD2.
Do you have any idea why that happens?
Best,
Tim
thaytan commented
The splitmuxsink problem is (hopefully) fixed in git master, but is triggered in this case by the lack of video input when the camera times out. That's not a condition that I've tested - it could be that there's something not being cleaned up right (although I've been quite careful about that), but it could also be that there's something in the underlying MMAL implementation and driver that doesn't get cleaned up completely and prevent reuse.
I can think of 2 useful pieces of diagnostic info:
- GST_DEBUG=rpi*:7 output - and compare what happens on the 2nd run vs the first.
- Delete the entire pipeline and recreate it for the 2nd run - if that works, it's more likely a problem in rpicamsrc than in the underlying MMAL.
TimSchneider42 commented
Hey,
thanks for your quick reply. I did both of the things you suggested.
- Setting the log level to rpi*:7 yields the following output: https://pastebin.com/s6aM6Q5v. I made it such that before each run "=======...===" is printed.
- Deleting the entire pipeline after each run works, the error does not occur.
Do you need any more information to debug this?
thaytan commented
The pastebin log disappeared already unfortunately. Can you attach it here?
TimSchneider42 commented
Oh, sorry I thought it stayed up there for a while:
0:00:00.006489000 1069 0x1448a80 INFO GST_INIT gstmessage.c:127:_priv_gst_message_initialize: init messages
0:00:00.019946000 1069 0x1448a80 INFO GST_INIT gstcontext.c:84:_priv_gst_context_initialize: init contexts
0:00:00.026164000 1069 0x1448a80 INFO GST_PLUGIN_LOADING gstplugin.c:317:_priv_gst_plugin_initialize: registering 0 static plugins
0:00:00.031049000 1069 0x1448a80 INFO GST_PLUGIN_LOADING gstplugin.c:225:gst_plugin_register_static: registered static plugin "staticelements"
0:00:00.033870000 1069 0x1448a80 INFO GST_PLUGIN_LOADING gstplugin.c:227:gst_plugin_register_static: added static plugin "staticelements", result: 1
0:00:00.036745000 1069 0x1448a80 INFO GST_REGISTRY gstregistry.c:1727:ensure_current_registry: reading registry cache: /home/pi/.cache/gstreamer-1.0/registry.arm.bin
0:00:00.368850000 1069 0x1448a80 INFO GST_REGISTRY gstregistrybinary.c:621:priv_gst_registry_binary_read_cache: loaded /home/pi/.cache/gstreamer-1.0/registry.arm.bin in 0.329015 seconds
0:00:00.372482000 1069 0x1448a80 INFO GST_REGISTRY gstregistry.c:1583:scan_and_update_registry: Validating plugins from registry cache: /home/pi/.cache/gstreamer-1.0/registry.arm.bin
0:00:00.398013000 1069 0x1448a80 INFO GST_REGISTRY gstregistry.c:1685:scan_and_update_registry: Registry cache has not changed
0:00:00.400884000 1069 0x1448a80 INFO GST_REGISTRY gstregistry.c:1762:ensure_current_registry: registry reading and updating done, result = 1
0:00:00.403652000 1069 0x1448a80 INFO GST_INIT gst.c:807:init_post: GLib runtime version: 2.58.3
0:00:00.406307000 1069 0x1448a80 INFO GST_INIT gst.c:809:init_post: GLib headers version: 2.58.1
0:00:00.406700000 1069 0x1448a80 INFO GST_INIT gst.c:810:init_post: initialized GStreamer successfully
0:00:00.443308000 1069 0x1448a80 INFO GST_PLUGIN_LOADING gstplugin.c:901:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/arm-linux-gnueabihf/gstreamer-1.0/libgstrpicamsrc.so" loaded
0:00:00.446119000 1069 0x1448a80 INFO GST_ELEMENT_FACTORY gstelementfactory.c:359:gst_element_factory_create: creating element "rpicamsrc" named "raspicam"
0:00:00.460421000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstelement.c:670:gst_element_add_pad:<GstBaseSrc@0x153a430> adding pad 'src'
0:00:00.463813000 1069 0x1448a80 DEBUG rpicamsrc gstrpicamsrc.c:659:gst_rpi_cam_src_set_orientation:<raspicam> set orientation identity
0:00:00.487930000 1069 0x1448a80 INFO GST_PLUGIN_LOADING gstplugin.c:901:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/arm-linux-gnueabihf/gstreamer-1.0/libgstvideoparsersbad.so" loaded
0:00:00.490931000 1069 0x1448a80 INFO GST_ELEMENT_FACTORY gstelementfactory.c:359:gst_element_factory_create: creating element "h264parse" named "h264parse"
0:00:00.495025000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstelement.c:670:gst_element_add_pad:<GstBaseParse@0x14a2078> adding pad 'sink'
0:00:00.498194000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstelement.c:670:gst_element_add_pad:<GstBaseParse@0x14a2078> adding pad 'src'
0:00:00.501545000 1069 0x1448a80 INFO baseparse gstbaseparse.c:3961:gst_base_parse_set_pts_interpolation:<GstH264Parse@0x14a2078> PTS interpolation: no
0:00:00.541565000 1069 0x1448a80 INFO GST_PLUGIN_LOADING gstplugin.c:901:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/arm-linux-gnueabihf/gstreamer-1.0/libgstmultifile.so" loaded
0:00:00.544361000 1069 0x1448a80 INFO GST_ELEMENT_FACTORY gstelementfactory.c:359:gst_element_factory_create: creating element "splitmuxsink" named "splitmuxsink"
0:00:00.549376000 1069 0x1448a80 INFO GST_ELEMENT_FACTORY gstelementfactory.c:359:gst_element_factory_create: creating element "pipeline" named "raspiwatch-pipeline"
0:00:00.553985000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstutils.c:1774:gst_element_link_pads_full: trying to link element raspicam:(any) to element h264parse:(any)
0:00:00.556804000 1069 0x1448a80 INFO GST_PADS gstutils.c:1035:gst_pad_check_link: trying to link raspicam:src and h264parse:sink
0:00:00.560096000 1069 0x1448a80 DEBUG rpicamsrc gstrpicamsrc.c:1297:gst_rpi_cam_src_get_caps:<raspicam> get_caps returning video/x-h264, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], stream-format=(string)byte-stream, alignment=(string)nal, profile=(string){ constrained-baseline, baseline, main, high }; image/jpeg, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ]; video/x-raw, format=(string){ I420, RGB, BGR, RGBA }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ]
0:00:00.563353000 1069 0x1448a80 INFO GST_PADS gstpad.c:4232:gst_pad_peer_query:<h264parse:src> pad has no peer
0:00:00.565233000 1069 0x1448a80 INFO GST_PADS gstutils.c:1588:prepare_link_maybe_ghosting: raspicam and h264parse in same bin, no need for ghost pads
0:00:00.567080000 1069 0x1448a80 INFO GST_PADS gstpad.c:2378:gst_pad_link_prepare: trying to link raspicam:src and h264parse:sink
0:00:00.569227000 1069 0x1448a80 DEBUG rpicamsrc gstrpicamsrc.c:1297:gst_rpi_cam_src_get_caps:<raspicam> get_caps returning video/x-h264, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ], stream-format=(string)byte-stream, alignment=(string)nal, profile=(string){ constrained-baseline, baseline, main, high }; image/jpeg, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ]; video/x-raw, format=(string){ I420, RGB, BGR, RGBA }, width=(int)[ 1, 2147483647 ], height=(int)[ 1, 2147483647 ], framerate=(fraction)[ 0/1, 2147483647/1 ]
0:00:00.571304000 1069 0x1448a80 INFO GST_PADS gstpad.c:4232:gst_pad_peer_query:<h264parse:src> pad has no peer
0:00:00.573150000 1069 0x1448a80 INFO GST_PADS gstpad.c:2586:gst_pad_link_full: linked raspicam:src and h264parse:sink, successful
0:00:00.574720000 1069 0x1448a80 INFO GST_EVENT gstevent.c:1517:gst_event_new_reconfigure: creating reconfigure event
0:00:00.575137000 1069 0x1448a80 INFO GST_EVENT gstpad.c:5808:gst_pad_send_event_unchecked:<raspicam:src> Received event on flushing pad. Discarding
0:00:00.576980000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstutils.c:1774:gst_element_link_pads_full: trying to link element h264parse:(any) to element splitmuxsink:(any)
0:00:00.599983000 1069 0x1448a80 INFO GST_PLUGIN_LOADING gstplugin.c:901:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/arm-linux-gnueabihf/gstreamer-1.0/libgstisomp4.so" loaded
0:00:00.602913000 1069 0x1448a80 INFO GST_ELEMENT_FACTORY gstelementfactory.c:359:gst_element_factory_create: creating element "mp4mux" named "muxer"
0:00:00.608233000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstelement.c:670:gst_element_add_pad:<GstMP4Mux@0x1557098> adding pad 'src'
0:00:00.613753000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstelement.c:670:gst_element_add_pad:<muxer> adding pad 'video_0'
0:00:00.626175000 1069 0x1448a80 INFO GST_PLUGIN_LOADING gstplugin.c:901:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/arm-linux-gnueabihf/gstreamer-1.0/libgstcoreelements.so" loaded
0:00:00.629009000 1069 0x1448a80 INFO GST_ELEMENT_FACTORY gstelementfactory.c:361:gst_element_factory_create: creating element "queue"
0:00:00.633951000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstelement.c:670:gst_element_add_pad:<GstQueue@0x15660c8> adding pad 'sink'
0:00:00.637223000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstelement.c:670:gst_element_add_pad:<GstQueue@0x15660c8> adding pad 'src'
0:00:00.640359000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<queue0> completed state change to NULL
0:00:00.643502000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstelement.c:920:gst_element_get_static_pad: found pad queue0:sink
0:00:00.645172000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstelement.c:920:gst_element_get_static_pad: found pad queue0:src
0:00:00.646934000 1069 0x1448a80 INFO GST_PADS gstpad.c:2378:gst_pad_link_prepare: trying to link queue0:src and muxer:video_0
0:00:00.648727000 1069 0x1448a80 INFO GST_PADS gstpad.c:4232:gst_pad_peer_query:<queue0:sink> pad has no peer
0:00:00.649403000 1069 0x1448a80 INFO GST_PADS gstpad.c:2586:gst_pad_link_full: linked queue0:src and muxer:video_0, successful
0:00:00.651147000 1069 0x1448a80 INFO GST_EVENT gstevent.c:1517:gst_event_new_reconfigure: creating reconfigure event
0:00:00.651567000 1069 0x1448a80 INFO GST_EVENT gstpad.c:5808:gst_pad_send_event_unchecked:<queue0:src> Received event on flushing pad. Discarding
0:00:00.655086000 1069 0x1448a80 INFO GST_PADS gstpad.c:2378:gst_pad_link_prepare: trying to link video:proxypad0 and queue0:sink
0:00:00.657839000 1069 0x1448a80 INFO GST_PADS gstpad.c:2586:gst_pad_link_full: linked video:proxypad0 and queue0:sink, successful
0:00:00.659642000 1069 0x1448a80 INFO GST_EVENT gstevent.c:1517:gst_event_new_reconfigure: creating reconfigure event
0:00:00.661549000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstelement.c:670:gst_element_add_pad:<splitmuxsink> adding pad 'video'
0:00:00.662147000 1069 0x1448a80 INFO GST_PADS gstutils.c:1588:prepare_link_maybe_ghosting: h264parse and splitmuxsink in same bin, no need for ghost pads
0:00:00.663966000 1069 0x1448a80 INFO GST_PADS gstpad.c:2378:gst_pad_link_prepare: trying to link h264parse:src and splitmuxsink:video
0:00:00.664982000 1069 0x1448a80 INFO GST_PADS gstpad.c:2586:gst_pad_link_full: linked h264parse:src and splitmuxsink:video, successful
0:00:00.667477000 1069 0x1448a80 INFO GST_EVENT gstevent.c:1517:gst_event_new_reconfigure: creating reconfigure event
0:00:00.668216000 1069 0x1448a80 INFO GST_EVENT gstpad.c:5808:gst_pad_send_event_unchecked:<h264parse:src> Received event on flushing pad. Discarding
=======================================================
0:00:00.672702000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<splitmuxsink> current NULL pending VOID_PENDING, desired next READY
0:00:00.674528000 1069 0x1448a80 INFO GST_ELEMENT_FACTORY gstelementfactory.c:359:gst_element_factory_create: creating element "filesink" named "sink"
0:00:00.678227000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstelement.c:670:gst_element_add_pad:<GstBaseSink@0x156e218> adding pad 'sink'
0:00:00.681231000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<sink> completed state change to NULL
0:00:00.683446000 1069 0x1448a80 INFO GST_ELEMENT_PADS gstutils.c:1774:gst_element_link_pads_full: trying to link element muxer:(any) to element sink:(any)
0:00:00.684914000 1069 0x1448a80 INFO GST_PADS gstutils.c:1035:gst_pad_check_link: trying to link muxer:src and sink:sink
0:00:00.685569000 1069 0x1448a80 INFO GST_PADS gstutils.c:1588:prepare_link_maybe_ghosting: muxer and sink in same bin, no need for ghost pads
0:00:00.687103000 1069 0x1448a80 INFO GST_PADS gstpad.c:2378:gst_pad_link_prepare: trying to link muxer:src and sink:sink
0:00:00.688642000 1069 0x1448a80 INFO GST_PADS gstpad.c:2586:gst_pad_link_full: linked muxer:src and sink:sink, successful
0:00:00.689038000 1069 0x1448a80 INFO GST_EVENT gstevent.c:1517:gst_event_new_reconfigure: creating reconfigure event
0:00:00.690357000 1069 0x1448a80 INFO GST_EVENT gstpad.c:5808:gst_pad_send_event_unchecked:<muxer:src> Received event on flushing pad. Discarding
0:00:00.691648000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'sink' changed state to 2(READY) successfully
0:00:00.693529000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<muxer> current NULL pending VOID_PENDING, desired next READY
0:00:00.695234000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<muxer> completed state change to READY
0:00:00.696950000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<muxer> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.698985000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'muxer' changed state to 2(READY) successfully
0:00:00.700927000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<queue0> current NULL pending VOID_PENDING, desired next READY
0:00:00.702644000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<queue0> completed state change to READY
0:00:00.703096000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<queue0> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.704933000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'queue0' changed state to 2(READY) successfully
0:00:00.706794000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<splitmuxsink> completed state change to READY
0:00:00.707240000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<splitmuxsink> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.709143000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'splitmuxsink' changed state to 2(READY) successfully
0:00:00.711184000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<h264parse> current NULL pending VOID_PENDING, desired next READY
0:00:00.712901000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<h264parse> completed state change to READY
0:00:00.713362000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<h264parse> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.715254000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'h264parse' changed state to 2(READY) successfully
0:00:00.717189000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<raspicam> current NULL pending VOID_PENDING, desired next READY
0:00:00.718893000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<raspicam> completed state change to READY
0:00:00.720758000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspicam> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:00.722611000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'raspicam' changed state to 2(READY) successfully
0:00:00.723187000 1069 0x1448a80 INFO GST_STATES gstelement.c:2651:gst_element_continue_state:<raspiwatch-pipeline> committing state from NULL to READY, pending PLAYING, next PAUSED
0:00:00.724895000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspiwatch-pipeline> notifying about state-changed NULL to READY (PLAYING pending)
0:00:00.726665000 1069 0x1448a80 INFO GST_STATES gstelement.c:2658:gst_element_continue_state:<raspiwatch-pipeline> continue state change READY to PAUSED, final PLAYING
0:00:00.728639000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<splitmuxsink> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.730773000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'sink' changed state to 3(PAUSED) successfully
0:00:00.732578000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<muxer> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.734469000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<muxer> completed state change to PAUSED
0:00:00.736148000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<muxer> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.738119000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'muxer' changed state to 3(PAUSED) successfully
0:00:00.739856000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<queue0> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.742293000 1069 0x1448a80 INFO task gsttask.c:457:gst_task_set_lock: setting stream lock 0x14a079c on task 0x1570028
0:00:00.743938000 1069 0x1448a80 INFO GST_PADS gstpad.c:6154:gst_pad_start_task:<queue0:src> created task 0x1570028
0:00:00.745105000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<queue0> completed state change to PAUSED
0:00:00.747944000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<queue0> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.748593000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'queue0' changed state to 3(PAUSED) successfully
0:00:00.752627000 1069 0x1448a80 INFO splitmuxsink gstsplitmuxsink.c:2345:do_async_start:<splitmuxsink> Sending async_start message
0:00:00.755619000 1069 0x1448a80 INFO GST_STATES gstbin.c:2960:gst_bin_change_state_func:<raspiwatch-pipeline> child 'splitmuxsink' is changing state asynchronously to PAUSED
0:00:00.757376000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<h264parse> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.762152000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<h264parse> completed state change to PAUSED
0:00:00.764877000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<h264parse> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.767740000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'h264parse' changed state to 3(PAUSED) successfully
0:00:00.770638000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<raspicam> current READY pending VOID_PENDING, desired next PAUSED
0:00:00.771204000 1069 0x1448a80 LOG rpicamsrc gstrpicamsrc.c:1195:gst_rpi_cam_src_start:<raspicam> In src_start()
0:00:00.788260000 1069 0x1448a80 INFO basesrc gstbasesrc.c:1358:gst_base_src_do_seek:<raspicam> seeking: time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:00.791425000 1069 0x1448a80 INFO task gsttask.c:457:gst_task_set_lock: setting stream lock 0x14a00e4 on task 0x15700d0
0:00:00.794141000 1069 0x1448a80 INFO GST_PADS gstpad.c:6154:gst_pad_start_task:<raspicam:src> created task 0x15700d0
0:00:00.797542000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<raspicam> completed state change to PAUSED
0:00:00.799259000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspicam> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:00.801256000 1069 0x1448a80 INFO GST_STATES gstbin.c:2997:gst_bin_change_state_func:<raspiwatch-pipeline> child 'raspicam' changed state to 3(PAUSED) successfully without preroll
0:00:00.803152000 1069 0x1448a80 INFO GST_STATES gstelement.c:2651:gst_element_continue_state:<raspiwatch-pipeline> committing state from READY to PAUSED, pending PLAYING, next PLAYING
0:00:00.803587000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspiwatch-pipeline> notifying about state-changed READY to PAUSED (PLAYING pending)
0:00:00.804069000 1069 0x1448a80 INFO GST_STATES gstelement.c:2658:gst_element_continue_state:<raspiwatch-pipeline> continue state change PAUSED to PLAYING, final PLAYING
0:00:00.807181000 1069 0x1448a80 INFO GST_EVENT gstevent.c:1388:gst_event_new_latency: creating latency event 0:00:00.000000000
0:00:00.809554000 1069 0x1537320 INFO GST_ELEMENT_PADS gstelement.c:917:gst_element_get_static_pad: no such pad 'sink' in element "raspicam"
0:00:00.814638000 1069 0x1537320 FIXME default gstutils.c:3981:gst_pad_create_stream_id_internal:<raspicam:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
0:00:00.816363000 1069 0x1448a80 INFO bin gstbin.c:2783:gst_bin_do_latency_func:<raspiwatch-pipeline> configured latency of 0:00:00.000000000
0:00:00.821653000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<splitmuxsink> current READY pending PAUSED, desired next PLAYING
0:00:00.824794000 1069 0x1448a80 INFO GST_STATES gstbin.c:2960:gst_bin_change_state_func:<raspiwatch-pipeline> child 'splitmuxsink' is changing state asynchronously to PLAYING
0:00:00.829275000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<h264parse> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:00.832185000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<h264parse> completed state change to PLAYING
0:00:00.834083000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<h264parse> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:00.827584000 1069 0x1537320 DEBUG rpicamsrc gstrpicamsrc.c:1297:gst_rpi_cam_src_get_caps:<raspicam> get_caps returning video/x-h264, width=(int)[ 1, 3240 ], height=(int)[ 1, 2464 ], framerate=(fraction)[ 0/1, 1000/1 ], stream-format=(string)byte-stream, alignment=(string)nal, profile=(string){ constrained-baseline, baseline, main, high }; image/jpeg, width=(int)[ 1, 3240 ], height=(int)[ 1, 2464 ], framerate=(fraction)[ 0/1, 1000/1 ]; video/x-raw, format=(string){ I420, RGB, BGR, RGBA }, width=(int)[ 1, 3240 ], height=(int)[ 1, 2464 ], framerate=(fraction)[ 0/1, 1000/1 ]
0:00:00.838564000 1069 0x1537320 DEBUG rpicamsrc gstrpicamsrc.c:1383:gst_rpi_cam_src_fixate:<raspicam> fixating caps video/x-h264, width=(int)[ 16, 3240 ], height=(int)[ 16, 2464 ], framerate=(fraction)[ 0/1, 1000/1 ], profile=(string){ constrained-baseline, baseline, main, high }, stream-format=(string)byte-stream, alignment=(string)nal
0:00:00.841826000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'h264parse' changed state to 4(PLAYING) successfully
0:00:00.844725000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<raspicam> completed state change to PLAYING
0:00:00.846500000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspicam> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:00.848463000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'raspicam' changed state to 4(PLAYING) successfully
0:00:00.850795000 1069 0x1537320 DEBUG rpicamsrc gstrpicamsrc.c:1394:gst_rpi_cam_src_fixate:<raspicam> fixated caps video/x-h264, width=(int)1920, height=(int)1080, framerate=(fraction)30/1, profile=(string){ constrained-baseline, baseline, main, high }, stream-format=(string)byte-stream, alignment=(string)nal
0:00:00.852831000 1069 0x1537320 DEBUG rpicamsrc gstrpicamsrc.c:1309:gst_rpi_cam_src_set_caps:<raspicam> In set_caps video/x-h264, width=(int)1920, height=(int)1080, framerate=(fraction)30/1, profile=(string)constrained-baseline, stream-format=(string)byte-stream, alignment=(string)nal
0:00:00.855224000 1069 0x1537320 INFO GST_EVENT gstevent.c:814:gst_event_new_caps: creating caps event video/x-h264, width=(int)1920, height=(int)1080, framerate=(fraction)30/1, profile=(string)constrained-baseline, stream-format=(string)byte-stream, alignment=(string)nal
0:00:00.863216000 1069 0x1537320 LOG rpicamsrc gstrpicamsrc.c:1374:gst_rpi_cam_src_decide_allocation:<raspicam> In decide_allocation
0:00:00.868739000 1069 0x1537320 DEBUG rpicamsrc RaspiCapture.c:1383:create_encoder_component: encoder wants 1 buffers of size 65536
0:00:00.873481000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:1550:create_encoder_component: Encoder component done
0:00:00.877078000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:310:dump_state: Width 1920, Height 1080
0:00:00.879002000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:312:dump_state: bitrate 1000000, framerate 30/1, time delay 5000
0:00:00.880812000 1069 0x1537320 LOG rpicamsrc RaspiPreview.c:226:raspipreview_dump_parameters: Preview Yes, Full screen Yes
0:00:00.882556000 1069 0x1537320 LOG rpicamsrc RaspiPreview.c:230:raspipreview_dump_parameters: Preview window 0,0,1024,768
Opacity 255
0:00:00.883085000 1069 0x1537320 LOG rpicamsrc RaspiCamControl.c:741:raspicamcontrol_dump_parameters: Sharpness 0, Contrast 0, Brightness 50
0:00:00.884740000 1069 0x1537320 LOG rpicamsrc RaspiCamControl.c:742:raspicamcontrol_dump_parameters: Saturation 0, ISO 0, Video Stabilisation No, Exposure compensation 0
0:00:00.885203000 1069 0x1537320 LOG rpicamsrc RaspiCamControl.c:744:raspicamcontrol_dump_parameters: Exposure Mode '1', AWB Mode '1', Image Effect '0'
0:00:00.886914000 1069 0x1537320 LOG rpicamsrc RaspiCamControl.c:746:raspicamcontrol_dump_parameters: Rotation 0, hflip No, vflip No
0:00:00.887408000 1069 0x1537320 LOG rpicamsrc RaspiCamControl.c:747:raspicamcontrol_dump_parameters: ROI x 0.000000, y 0.000000, w 1.000000 h 1.000000
0:00:00.970880000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:1273:raspi_capture_set_format_and_start: Camera component done
0:00:00.974754000 1069 0x1537320 DEBUG rpicamsrc RaspiCapture.c:1718:raspi_capture_start: Creating pool of 1 buffers of size 65536
0:00:00.977962000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:1731:raspi_capture_start: Starting component connection stage
0:00:00.979698000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:1737:raspi_capture_start: Connecting camera preview port to preview input port
0:00:00.981430000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:1738:raspi_capture_start: Starting video preview
0:00:00.993597000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:1752:raspi_capture_start: Connecting camera video port to encoder input port
0:00:01.009947000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:1772:raspi_capture_start: Enabling encoder output port
0:00:01.012671000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:1799:raspi_capture_start: Starting video capture
0:00:01.017545000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:977:raspi_capture_fill_buffer: Buf (uS) PTS 0 DTS -9223372036854775808 STC 342806527 (latency 342806527uS) TS 99:99:99.999999999
0:00:01.019689000 1069 0x1537320 LOG rpicamsrc gstrpicamsrc.c:1435:gst_rpi_cam_src_create:<raspicam> Made buffer of size 28
0:00:01.020331000 1069 0x1537320 INFO GST_EVENT gstevent.c:895:gst_event_new_segment: creating segment event time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:01.022522000 1069 0x1537320 INFO basesrc gstbasesrc.c:2945:gst_base_src_loop:<raspicam> marking pending DISCONT
0:00:01.105310000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:977:raspi_capture_fill_buffer: Buf (uS) PTS 342814467 DTS -9223372036854775808 STC 342894349 (latency 79882uS) TS 0:00:00.218568000
0:00:01.107819000 1069 0x1537320 LOG rpicamsrc gstrpicamsrc.c:1435:gst_rpi_cam_src_create:<raspicam> Made buffer of size 27360
0:00:01.137648000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:977:raspi_capture_fill_buffer: Buf (uS) PTS 342847779 DTS -9223372036854775808 STC 342926645 (latency 78866uS) TS 0:00:00.251865000
0:00:01.141288000 1069 0x1537320 LOG rpicamsrc gstrpicamsrc.c:1435:gst_rpi_cam_src_create:<raspicam> Made buffer of size 13729
0:00:01.146644000 1069 0x1537320 INFO baseparse gstbaseparse.c:4004:gst_base_parse_set_latency:<h264parse> min/max latency 0:00:00.033333333, 0:00:00.033333333
0:00:01.151192000 1069 0x1537320 INFO GST_EVENT gstevent.c:814:gst_event_new_caps: creating caps event video/x-h264, width=(int)1920, height=(int)1080, framerate=(fraction)30/1, profile=(string)constrained-baseline, stream-format=(string)avc, alignment=(string)au, interlace-mode=(string)progressive, chroma-format=(string)4:2:0, bit-depth-luma=(uint)8, bit-depth-chroma=(uint)8, parsed=(boolean)true, level=(string)4, codec_data=(buffer)0142c028ffe1000f2742c02895a01e0089f9601e244d4001000528ce013720
0:00:01.162693000 1069 0x1537320 INFO splitmuxsink gstsplitmuxsink.c:1746:handle_mq_input:<queue0:sink> Have keyframe with running time +0:00:00.000000000
0:00:01.167117000 1069 0x15372c0 INFO GST_STATES gstelement.c:2651:gst_element_continue_state:<muxer> committing state from PAUSED to READY, pending NULL, next NULL
0:00:01.170683000 1069 0x15372c0 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<muxer> notifying about state-changed PAUSED to READY (NULL pending)
0:00:01.174402000 1069 0x15372c0 INFO GST_STATES gstelement.c:2658:gst_element_continue_state:<muxer> continue state change READY to NULL, final NULL
0:00:01.179167000 1069 0x15372c0 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<muxer> completed state change to NULL
0:00:01.182903000 1069 0x15372c0 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<muxer> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:01.182595000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:977:raspi_capture_fill_buffer: Buf (uS) PTS 342881091 DTS -9223372036854775808 STC 342966365 (latency 85274uS) TS 0:00:00.285158000
0:00:01.188275000 1069 0x1537320 LOG rpicamsrc gstrpicamsrc.c:1435:gst_rpi_cam_src_create:<raspicam> Made buffer of size 7252
0:00:01.190706000 1069 0x15372c0 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<sink> completed state change to NULL
0:00:01.204449000 1069 0x1537320 LOG rpicamsrc RaspiCapture.c:977:raspi_capture_fill_buffer: Buf (uS) PTS 342914403 DTS -9223372036854775808 STC 342993420 (latency 79017uS) TS 0:00:00.318498000
0:00:01.207832000 1069 0x1537320 LOG rpicamsrc gstrpicamsrc.c:1435:gst_rpi_cam_src_create:<raspicam> Made buffer of size 13075
0:00:01.210954000 1069 0x1537320 INFO basesrc gstbasesrc.c:2839:gst_base_src_loop:<raspicam> pausing after gst_base_src_get_range() = flushing
0:00:01.213841000 1069 0x1537320 INFO task gsttask.c:316:gst_task_func:<raspicam:src> Task going to paused
0:00:01.214509000 1069 0x15372c0 INFO splitmuxsink gstsplitmuxsink.c:2325:set_next_filename:<splitmuxsink> Setting file to output00.mp4
0:00:01.215201000 1069 0x15372c0 INFO filesink gstfilesink.c:294:gst_file_sink_set_location:<sink> filename : output00.mp4
0:00:01.215614000 1069 0x15372c0 INFO filesink gstfilesink.c:295:gst_file_sink_set_location:<sink> uri : file:///tmp/tmp.75VS08s2Cx/recorder/cmake-build-debug/output00.mp4
0:00:01.218289000 1069 0x15372c0 INFO GST_STATES gstelement.c:2651:gst_element_continue_state:<sink> committing state from NULL to READY, pending PAUSED, next PAUSED
0:00:01.220201000 1069 0x15372c0 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<sink> notifying about state-changed NULL to READY (PAUSED pending)
0:00:01.223079000 1069 0x15372c0 INFO GST_STATES gstelement.c:2658:gst_element_continue_state:<sink> continue state change READY to PAUSED, final PAUSED
0:00:01.226826000 1069 0x15372c0 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<sink> completed state change to PAUSED
0:00:01.227427000 1069 0x15372c0 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<sink> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:01.221921000 1069 0x1537320 INFO task gsttask.c:318:gst_task_func:<raspicam:src> Task resume from paused
0:00:01.230259000 1069 0x1537320 INFO basesrc gstbasesrc.c:2839:gst_base_src_loop:<raspicam> pausing after gst_base_src_get_range() = eos
0:00:01.231868000 1069 0x1537320 INFO splitmuxsink gstsplitmuxsink.c:1595:handle_mq_input:<splitmuxsink> Got Reference EOS. Finishing up
0:00:01.236362000 1069 0x1537320 INFO task gsttask.c:316:gst_task_func:<raspicam:src> Task going to paused
0:00:01.234323000 1069 0x15372c0 INFO GST_STATES gstelement.c:2651:gst_element_continue_state:<muxer> committing state from NULL to READY, pending PAUSED, next PAUSED
0:00:01.243946000 1069 0x15372c0 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<muxer> notifying about state-changed NULL to READY (PAUSED pending)
0:00:01.245595000 1069 0x15372c0 INFO GST_STATES gstelement.c:2658:gst_element_continue_state:<muxer> continue state change READY to PAUSED, final PAUSED
0:00:01.247806000 1069 0x15372c0 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<muxer> completed state change to PAUSED
0:00:01.249738000 1069 0x15372c0 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<muxer> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:01.252647000 1069 0x15372c0 INFO splitmuxsink gstsplitmuxsink.c:2357:do_async_done:<splitmuxsink> Sending async_done message
0:00:01.254755000 1069 0x15372c0 INFO GST_STATES gstbin.c:3424:bin_handle_async_done:<splitmuxsink> committing state from READY to PAUSED, old pending PAUSED
0:00:01.256668000 1069 0x15372c0 INFO GST_STATES gstbin.c:3444:bin_handle_async_done:<splitmuxsink> completed state change, pending VOID
0:00:01.257290000 1069 0x15372c0 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<splitmuxsink> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:01.260716000 1069 0x15372c0 INFO GST_STATES gstbin.c:3433:bin_handle_async_done:<raspiwatch-pipeline> setting state from PAUSED to PAUSED, pending PLAYING
0:00:01.263098000 1069 0x15372c0 INFO GST_STATES gstbin.c:3453:bin_handle_async_done:<raspiwatch-pipeline> continue state change, pending PLAYING
0:00:01.271807000 1069 0x15372c0 FIXME basesink gstbasesink.c:3145:gst_base_sink_default_event:<sink> stream-start event without group-id. Consider implementing group-id handling in the upstream elements
0:00:01.273731000 1069 0xb3503290 INFO GST_STATES gstbin.c:3250:gst_bin_continue_func:<raspiwatch-pipeline> continue state change PAUSED to PLAYING, final PLAYING
0:00:01.280302000 1069 0xb3503290 INFO GST_EVENT gstevent.c:1388:gst_event_new_latency: creating latency event 0:00:00.000000000
0:00:01.284737000 1069 0x15372c0 INFO GST_EVENT gstevent.c:814:gst_event_new_caps: creating caps event video/quicktime, variant=(string)iso
0:00:01.288362000 1069 0x15372c0 INFO qtmux gstqtmux.c:2197:gst_qt_mux_downstream_is_seekable:<muxer> downstream is seekable
0:00:01.292968000 1069 0xb3503290 INFO bin gstbin.c:2783:gst_bin_do_latency_func:<raspiwatch-pipeline> configured latency of 0:00:00.000000000
0:00:01.296723000 1069 0xb3503290 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<splitmuxsink> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:01.299900000 1069 0x15372c0 INFO GST_EVENT gstevent.c:895:gst_event_new_segment: creating segment event bytes segment start=0, offset=0, stop=-1, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0, base=0, position 0, duration -1
0:00:01.302851000 1069 0xb3503290 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<sink> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:01.312347000 1069 0xb3503290 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<sink> completed state change to PLAYING
0:00:01.315456000 1069 0xb3503290 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<sink> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:01.319302000 1069 0xb3503290 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'sink' changed state to 4(PLAYING) successfully
0:00:01.322457000 1069 0xb3503290 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<muxer> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:01.328685000 1069 0xb3503290 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<muxer> completed state change to PLAYING
0:00:01.332095000 1069 0xb3503290 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<muxer> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:01.326922000 1069 0x15372c0 INFO GST_EVENT gstevent.c:814:gst_event_new_caps: creating caps event video/quicktime, variant=(string)iso, streamheader=(buffer)< 000003506d6f6f760000006c6d76686400000000dbd38464dbd3846400000bb8000003bb00010000010000000000000000000000000100000000000000000000000000000001000000000000000000000000000040000000000000000000000000000000000000000000000000000000000000020000029f7472616b0000005c746b686400000007dbd38464dbd384640000000100000000000003bb00000000000000000000000000000000000100000000000000000000000000000001000000000000000000000000000040000000001000000009000000000024656474730000001c656c73740000000000000001000003bb0000000000010000000001da6d646961000000206d64686400000000dbd38464dbd3846400000bb8000003bb55c400000000002d68646c72000000000000000076696465000000000000000000000000566964656f48616e646c657200000001856d696e6600000014766d68640000000100000000000000000000002464696e660000001c6472656600000000000000010000000c75726c2000000001000001457374626c000000b1737473640000000000000001000000a16176633100000000000000010000000000000000000000000000000007800438004800000048000000000000000100000000000000000000000000000000000000000000000000000000000000000018ffff00000027617663430142c028ffe1000f2742c02895a01e0089f9601e244d4001000528ce01372000000014627472740000000000000000001289e9000000107061737000000001000000010000002873747473000000000000000300000001000002f40000000100000063000000010000006400000014737473730000000000000001000000010000001c737473630000000000000001000000010000000300000001000000207374737a00000000000000000000000300006afc000035a100001c54000000147374636f0000000000000001000000300000003d75647461000000356d657461000000000000002168646c72000000006d686c726d6469720000000000000000000000000000000008696c73740000003d75647461000000356d657461000000000000002168646c72000000006d686c726d6469720000000000000000000000000000000008696c7374 >
0:00:01.341305000 1069 0x15372c0 INFO GST_EVENT gstevent.c:895:gst_event_new_segment: creating segment event bytes segment start=32, offset=0, stop=-1, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0, base=0, position 0, duration -1
0:00:01.338376000 1069 0xb3503290 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'muxer' changed state to 4(PLAYING) successfully
0:00:01.346711000 1069 0xb3503290 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<queue0> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:01.347193000 1069 0xb3503290 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<queue0> completed state change to PLAYING
0:00:01.347604000 1069 0xb3503290 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<queue0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:01.351313000 1069 0xb3503290 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'queue0' changed state to 4(PLAYING) successfully
0:00:01.354438000 1069 0xb3503290 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<splitmuxsink> completed state change to PLAYING
0:00:01.358450000 1069 0xb3503290 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<splitmuxsink> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:01.359049000 1069 0x15372c0 INFO task gsttask.c:316:gst_task_func:<queue0:src> Task going to paused
0:00:01.362562000 1069 0xb3503290 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'splitmuxsink' changed state to 4(PLAYING) successfully
0:00:01.365713000 1069 0xb3503290 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<h264parse> current PLAYING pending VOID_PENDING, desired next PLAYING
0:00:01.367679000 1069 0xb3503290 INFO GST_STATES gstbin.c:2623:gst_bin_element_set_state:<h264parse> skipping transition from PLAYING to PLAYING
0:00:01.369678000 1069 0xb3503290 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'h264parse' changed state to 4(PLAYING) successfully
0:00:01.370567000 1069 0xb3503290 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<raspicam> current PLAYING pending VOID_PENDING, desired next PLAYING
0:00:01.372464000 1069 0xb3503290 INFO GST_STATES gstbin.c:2623:gst_bin_element_set_state:<raspicam> skipping transition from PLAYING to PLAYING
0:00:01.372941000 1069 0xb3503290 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'raspicam' changed state to 4(PLAYING) successfully
0:00:01.374949000 1069 0xb3503290 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<raspiwatch-pipeline> completed state change to PLAYING
0:00:01.376949000 1069 0xb3503290 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspiwatch-pipeline> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
End-Of-Stream reached.
Stopping
0:00:01.383836000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<splitmuxsink> current PLAYING pending VOID_PENDING, desired next PAUSED
0:00:01.384542000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<sink> current PLAYING pending VOID_PENDING, desired next PAUSED
0:00:01.386482000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<sink> completed state change to PAUSED
0:00:01.387050000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<sink> notifying about state-changed PLAYING to PAUSED (VOID_PENDING pending)
0:00:01.387668000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'sink' changed state to 3(PAUSED) successfully
0:00:01.389607000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<muxer> current PLAYING pending VOID_PENDING, desired next PAUSED
0:00:01.391958000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<muxer> completed state change to PAUSED
0:00:01.392440000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<muxer> notifying about state-changed PLAYING to PAUSED (VOID_PENDING pending)
0:00:01.393044000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'muxer' changed state to 3(PAUSED) successfully
0:00:01.395356000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<queue0> current PLAYING pending VOID_PENDING, desired next PAUSED
0:00:01.395941000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<queue0> completed state change to PAUSED
0:00:01.397849000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<queue0> notifying about state-changed PLAYING to PAUSED (VOID_PENDING pending)
0:00:01.398573000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'queue0' changed state to 3(PAUSED) successfully
0:00:01.400663000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<splitmuxsink> completed state change to PAUSED
0:00:01.402777000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<splitmuxsink> notifying about state-changed PLAYING to PAUSED (VOID_PENDING pending)
0:00:01.403485000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'splitmuxsink' changed state to 3(PAUSED) successfully
0:00:01.405587000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<h264parse> current PLAYING pending VOID_PENDING, desired next PAUSED
0:00:01.406113000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<h264parse> completed state change to PAUSED
0:00:01.408053000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<h264parse> notifying about state-changed PLAYING to PAUSED (VOID_PENDING pending)
0:00:01.408756000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'h264parse' changed state to 3(PAUSED) successfully
0:00:01.411368000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<raspicam> current PLAYING pending VOID_PENDING, desired next PAUSED
0:00:01.413491000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<raspicam> completed state change to PAUSED
0:00:01.413952000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspicam> notifying about state-changed PLAYING to PAUSED (VOID_PENDING pending)
0:00:01.415961000 1069 0x1448a80 INFO GST_STATES gstbin.c:2997:gst_bin_change_state_func:<raspiwatch-pipeline> child 'raspicam' changed state to 3(PAUSED) successfully without preroll
0:00:01.416577000 1069 0x1448a80 INFO GST_STATES gstelement.c:2651:gst_element_continue_state:<raspiwatch-pipeline> committing state from PLAYING to PAUSED, pending NULL, next READY
0:00:01.418645000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspiwatch-pipeline> notifying about state-changed PLAYING to PAUSED (NULL pending)
0:00:01.419233000 1069 0x1448a80 INFO GST_STATES gstelement.c:2658:gst_element_continue_state:<raspiwatch-pipeline> continue state change PAUSED to READY, final NULL
0:00:01.421549000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<splitmuxsink> current PAUSED pending VOID_PENDING, desired next READY
0:00:01.423933000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<sink> current PAUSED pending VOID_PENDING, desired next READY
0:00:01.426522000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<sink> completed state change to READY
0:00:01.428579000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<sink> notifying about state-changed PAUSED to READY (VOID_PENDING pending)
0:00:01.429310000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'sink' changed state to 2(READY) successfully
0:00:01.431069000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<muxer> current PAUSED pending VOID_PENDING, desired next READY
0:00:01.432581000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<muxer> completed state change to READY
0:00:01.436011000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<muxer> notifying about state-changed PAUSED to READY (VOID_PENDING pending)
0:00:01.438185000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'muxer' changed state to 2(READY) successfully
0:00:01.440201000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<queue0> current PAUSED pending VOID_PENDING, desired next READY
0:00:01.441005000 1069 0x15372c0 INFO task gsttask.c:318:gst_task_func:<queue0:src> Task resume from paused
0:00:01.443854000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<queue0> completed state change to READY
0:00:01.445943000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<queue0> notifying about state-changed PAUSED to READY (VOID_PENDING pending)
0:00:01.448130000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'queue0' changed state to 2(READY) successfully
0:00:01.450425000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<splitmuxsink> completed state change to READY
0:00:01.452733000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<splitmuxsink> notifying about state-changed PAUSED to READY (VOID_PENDING pending)
0:00:01.453761000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'splitmuxsink' changed state to 2(READY) successfully
0:00:01.456141000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<h264parse> current PAUSED pending VOID_PENDING, desired next READY
0:00:01.457723000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<h264parse> completed state change to READY
0:00:01.461530000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<h264parse> notifying about state-changed PAUSED to READY (VOID_PENDING pending)
0:00:01.462246000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'h264parse' changed state to 2(READY) successfully
0:00:01.464556000 1069 0x1537320 INFO task gsttask.c:318:gst_task_func:<raspicam:src> Task resume from paused
0:00:01.465490000 1069 0x1448a80 LOG rpicamsrc RaspiCapture.c:1858:raspi_capture_stop: Closing down
0:00:01.532033000 1069 0x1448a80 LOG rpicamsrc RaspiCapture.c:1904:raspi_capture_free: Close down completed, all components disconnected, disabled and destroyed
0:00:01.537273000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<raspicam> completed state change to READY
0:00:01.539064000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspicam> notifying about state-changed PAUSED to READY (VOID_PENDING pending)
0:00:01.539687000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'raspicam' changed state to 2(READY) successfully
0:00:01.541664000 1069 0x1448a80 INFO GST_STATES gstelement.c:2651:gst_element_continue_state:<raspiwatch-pipeline> committing state from PAUSED to READY, pending NULL, next NULL
0:00:01.543335000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspiwatch-pipeline> notifying about state-changed PAUSED to READY (NULL pending)
0:00:01.545115000 1069 0x1448a80 INFO GST_STATES gstelement.c:2658:gst_element_continue_state:<raspiwatch-pipeline> continue state change READY to NULL, final NULL
0:00:01.545788000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<splitmuxsink> current READY pending VOID_PENDING, desired next NULL
0:00:01.548003000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<sink> current READY pending VOID_PENDING, desired next NULL
0:00:01.551947000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<sink> completed state change to NULL
0:00:01.553686000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<sink> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:01.555653000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'sink' changed state to 1(NULL) successfully
0:00:01.556977000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<muxer> current READY pending VOID_PENDING, desired next NULL
0:00:01.559394000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<muxer> completed state change to NULL
0:00:01.559835000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<muxer> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:01.560366000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'muxer' changed state to 1(NULL) successfully
0:00:01.562364000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<queue0> current READY pending VOID_PENDING, desired next NULL
0:00:01.562917000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<queue0> completed state change to NULL
0:00:01.564596000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<queue0> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:01.565198000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'queue0' changed state to 1(NULL) successfully
0:00:01.567003000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<splitmuxsink> completed state change to NULL
0:00:01.568695000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<splitmuxsink> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:01.569314000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'splitmuxsink' changed state to 1(NULL) successfully
0:00:01.571339000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<h264parse> current READY pending VOID_PENDING, desired next NULL
0:00:01.571877000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<h264parse> completed state change to NULL
0:00:01.573562000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<h264parse> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:01.575328000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'h264parse' changed state to 1(NULL) successfully
0:00:01.575861000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<raspicam> current READY pending VOID_PENDING, desired next NULL
0:00:01.577635000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<raspicam> completed state change to NULL
0:00:01.579371000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspicam> notifying about state-changed READY to NULL (VOID_PENDING pending)
0:00:01.579969000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'raspicam' changed state to 1(NULL) successfully
0:00:01.582533000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<raspiwatch-pipeline> completed state change to NULL
0:00:01.584230000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspiwatch-pipeline> notifying about state-changed READY to NULL (VOID_PENDING pending)
=======================================================
0:00:01.587781000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<splitmuxsink> current NULL pending VOID_PENDING, desired next READY
0:00:01.588466000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<sink> current NULL pending VOID_PENDING, desired next READY
0:00:01.592151000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<sink> completed state change to READY
0:00:01.593871000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<sink> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:01.595840000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'sink' changed state to 2(READY) successfully
0:00:01.597666000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<muxer> current NULL pending VOID_PENDING, desired next READY
0:00:01.598129000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<muxer> completed state change to READY
0:00:01.598521000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<muxer> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:01.600373000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'muxer' changed state to 2(READY) successfully
0:00:01.602412000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<queue0> current NULL pending VOID_PENDING, desired next READY
0:00:01.604123000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<queue0> completed state change to READY
0:00:01.604579000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<queue0> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:01.606406000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'queue0' changed state to 2(READY) successfully
0:00:01.606906000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<splitmuxsink> completed state change to READY
0:00:01.608569000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<splitmuxsink> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:01.610401000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'splitmuxsink' changed state to 2(READY) successfully
0:00:01.612403000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<h264parse> current NULL pending VOID_PENDING, desired next READY
0:00:01.612865000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<h264parse> completed state change to READY
0:00:01.614571000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<h264parse> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:01.615157000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'h264parse' changed state to 2(READY) successfully
0:00:01.616925000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<raspicam> current NULL pending VOID_PENDING, desired next READY
0:00:01.617383000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<raspicam> completed state change to READY
0:00:01.617770000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspicam> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:01.619701000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'raspicam' changed state to 2(READY) successfully
0:00:01.621592000 1069 0x1448a80 INFO GST_STATES gstelement.c:2651:gst_element_continue_state:<raspiwatch-pipeline> committing state from NULL to READY, pending PLAYING, next PAUSED
0:00:01.622039000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspiwatch-pipeline> notifying about state-changed NULL to READY (PLAYING pending)
0:00:01.622516000 1069 0x1448a80 INFO GST_STATES gstelement.c:2658:gst_element_continue_state:<raspiwatch-pipeline> continue state change READY to PAUSED, final PLAYING
0:00:01.624468000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<splitmuxsink> current READY pending VOID_PENDING, desired next PAUSED
0:00:01.626488000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<sink> current READY pending VOID_PENDING, desired next PAUSED
0:00:01.628296000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<sink> completed state change to PAUSED
0:00:01.628741000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<sink> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:01.630701000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'sink' changed state to 3(PAUSED) successfully
0:00:01.631260000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<muxer> current READY pending VOID_PENDING, desired next PAUSED
0:00:01.633113000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<muxer> completed state change to PAUSED
0:00:01.634842000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<muxer> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:01.635440000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'muxer' changed state to 3(PAUSED) successfully
0:00:01.637587000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<queue0> current READY pending VOID_PENDING, desired next PAUSED
0:00:01.638278000 1069 0x1448a80 INFO task gsttask.c:457:gst_task_set_lock: setting stream lock 0x14a079c on task 0x1570178
0:00:01.638655000 1069 0x1448a80 INFO GST_PADS gstpad.c:6154:gst_pad_start_task:<queue0:src> created task 0x1570178
0:00:01.641432000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<queue0> completed state change to PAUSED
0:00:01.644265000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<queue0> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:01.644903000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<splitmuxsink> child 'queue0' changed state to 3(PAUSED) successfully
0:00:01.646836000 1069 0x1448a80 INFO splitmuxsink gstsplitmuxsink.c:2345:do_async_start:<splitmuxsink> Sending async_start message
0:00:01.648582000 1069 0x1448a80 INFO GST_STATES gstbin.c:2960:gst_bin_change_state_func:<raspiwatch-pipeline> child 'splitmuxsink' is changing state asynchronously to PAUSED
0:00:01.650433000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<h264parse> current READY pending VOID_PENDING, desired next PAUSED
0:00:01.652787000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<h264parse> completed state change to PAUSED
0:00:01.655577000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<h264parse> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:01.658442000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'h264parse' changed state to 3(PAUSED) successfully
0:00:01.660227000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<raspicam> current READY pending VOID_PENDING, desired next PAUSED
0:00:01.660840000 1069 0x1448a80 LOG rpicamsrc gstrpicamsrc.c:1195:gst_rpi_cam_src_start:<raspicam> In src_start()
0:00:01.677679000 1069 0x1448a80 INFO basesrc gstbasesrc.c:1358:gst_base_src_do_seek:<raspicam> seeking: time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:01.680759000 1069 0x1448a80 INFO task gsttask.c:457:gst_task_set_lock: setting stream lock 0x14a00e4 on task 0x1570220
0:00:01.683520000 1069 0x1448a80 INFO GST_PADS gstpad.c:6154:gst_pad_start_task:<raspicam:src> created task 0x1570220
0:00:01.686915000 1069 0x1537320 INFO GST_ELEMENT_PADS gstelement.c:917:gst_element_get_static_pad: no such pad 'sink' in element "raspicam"
0:00:01.689730000 1069 0x1537320 FIXME default gstutils.c:3981:gst_pad_create_stream_id_internal:<raspicam:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
0:00:01.693293000 1069 0x1537320 DEBUG rpicamsrc gstrpicamsrc.c:1297:gst_rpi_cam_src_get_caps:<raspicam> get_caps returning video/x-h264, width=(int)[ 1, 3240 ], height=(int)[ 1, 2464 ], framerate=(fraction)[ 0/1, 1000/1 ], stream-format=(string)byte-stream, alignment=(string)nal, profile=(string){ constrained-baseline, baseline, main, high }; image/jpeg, width=(int)[ 1, 3240 ], height=(int)[ 1, 2464 ], framerate=(fraction)[ 0/1, 1000/1 ]; video/x-raw, format=(string){ I420, RGB, BGR, RGBA }, width=(int)[ 1, 3240 ], height=(int)[ 1, 2464 ], framerate=(fraction)[ 0/1, 1000/1 ]
0:00:01.699076000 1069 0x1537320 DEBUG rpicamsrc gstrpicamsrc.c:1383:gst_rpi_cam_src_fixate:<raspicam> fixating caps video/x-h264, width=(int)[ 16, 3240 ], height=(int)[ 16, 2464 ], framerate=(fraction)[ 0/1, 1000/1 ], profile=(string){ constrained-baseline, baseline, main, high }, stream-format=(string)byte-stream, alignment=(string)nal
0:00:01.695078000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<raspicam> completed state change to PAUSED
0:00:01.704636000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspicam> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:01.707520000 1069 0x1448a80 INFO GST_STATES gstbin.c:2997:gst_bin_change_state_func:<raspiwatch-pipeline> child 'raspicam' changed state to 3(PAUSED) successfully without preroll
0:00:01.709366000 1069 0x1448a80 INFO GST_STATES gstelement.c:2651:gst_element_continue_state:<raspiwatch-pipeline> committing state from READY to PAUSED, pending PLAYING, next PLAYING
0:00:01.711236000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspiwatch-pipeline> notifying about state-changed READY to PAUSED (PLAYING pending)
0:00:01.711781000 1069 0x1448a80 INFO GST_STATES gstelement.c:2658:gst_element_continue_state:<raspiwatch-pipeline> continue state change PAUSED to PLAYING, final PLAYING
0:00:01.713199000 1069 0x1448a80 INFO GST_EVENT gstevent.c:1388:gst_event_new_latency: creating latency event 0:00:00.000000000
0:00:01.716496000 1069 0x1537320 DEBUG rpicamsrc gstrpicamsrc.c:1394:gst_rpi_cam_src_fixate:<raspicam> fixated caps video/x-h264, width=(int)1920, height=(int)1080, framerate=(fraction)30/1, profile=(string){ constrained-baseline, baseline, main, high }, stream-format=(string)byte-stream, alignment=(string)nal
0:00:01.718476000 1069 0x1537320 DEBUG rpicamsrc gstrpicamsrc.c:1309:gst_rpi_cam_src_set_caps:<raspicam> In set_caps video/x-h264, width=(int)1920, height=(int)1080, framerate=(fraction)30/1, profile=(string)constrained-baseline, stream-format=(string)byte-stream, alignment=(string)nal
0:00:01.719118000 1069 0x1537320 INFO GST_EVENT gstevent.c:814:gst_event_new_caps: creating caps event video/x-h264, width=(int)1920, height=(int)1080, framerate=(fraction)30/1, profile=(string)constrained-baseline, stream-format=(string)byte-stream, alignment=(string)nal
0:00:01.722733000 1069 0x1537320 LOG rpicamsrc gstrpicamsrc.c:1374:gst_rpi_cam_src_decide_allocation:<raspicam> In decide_allocation
0:00:01.726300000 1069 0x1448a80 INFO bin gstbin.c:2783:gst_bin_do_latency_func:<raspiwatch-pipeline> configured latency of 0:00:00.000000000
0:00:01.729240000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<splitmuxsink> current READY pending PAUSED, desired next PLAYING
0:00:01.732165000 1069 0x1448a80 INFO GST_STATES gstbin.c:2960:gst_bin_change_state_func:<raspiwatch-pipeline> child 'splitmuxsink' is changing state asynchronously to PLAYING
0:00:01.734035000 1069 0x1448a80 INFO GST_STATES gstbin.c:2506:gst_bin_element_set_state:<h264parse> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:01.736039000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<h264parse> completed state change to PLAYING
0:00:01.737725000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<h264parse> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:01.738493000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'h264parse' changed state to 4(PLAYING) successfully
0:00:01.740566000 1069 0x1448a80 INFO GST_STATES gstelement.c:2676:gst_element_continue_state:<raspicam> completed state change to PLAYING
0:00:01.742333000 1069 0x1448a80 INFO GST_STATES gstelement.c:2579:_priv_gst_element_state_changed:<raspicam> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:01.744148000 1069 0x1448a80 INFO GST_STATES gstbin.c:2954:gst_bin_change_state_func:<raspiwatch-pipeline> child 'raspicam' changed state to 4(PLAYING) successfully
0:00:02.240749000 1069 0x1537320 WARN rpicamsrc gstrpicamsrc.c:1445:gst_rpi_cam_src_create:<raspicam> error: Camera capture timed out.
0:00:02.243536000 1069 0x1537320 WARN rpicamsrc gstrpicamsrc.c:1445:gst_rpi_cam_src_create:<raspicam> error: Waiting for a buffer from the camera took too long.
0:00:02.246412000 1069 0x1537320 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<raspicam> posting message: Camera capture timed out.
0:00:02.249525000 1069 0x1537320 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<raspicam> posted error message: Camera capture timed out.
0:00:02.253081000 1069 0x1537320 INFO basesrc gstbasesrc.c:2839:gst_base_src_loop:<raspicam> pausing after gst_base_src_get_range() = error
0:00:02.254982000 1069 0x1537320 WARN basesrc gstbasesrc.c:3055:gst_base_src_loop:<raspicam> error: Internal data stream error.
Error received from element raspicam: Camera capture timed out.
Debugging information: gstrpicamsrc.c(1445): gst_rpi_cam_src_create (): /GstPipeline:raspiwatch-pipeline/GstRpiCamSrc:raspicam:
Waiting for a buffer from the camera took too long.
Error received from element raspicam: Camera capture timed out.
Debugging information: gstrpicamsrc.c(1445): gst_rpi_cam_src_create (): /GstPipeline:raspiwatch-pipeline/GstRpiCamSrc:raspicam:
Waiting for a buffer from the camera took too long.
0:00:02.261500000 1069 0x1537320 WARN basesrc gstbasesrc.c:3055:gst_base_src_loop:<raspicam> error: streaming stopped, reason error (-5)
0:00:02.262129000 1069 0x1537320 INFO GST_ERROR_SYSTEM gstelement.c:2145:gst_element_message_full_with_details:<raspicam> posting message: Internal data stream error.
Error received from element raspicam: Internal data stream error.
Debugging information: gstbasesrc.c(3055): gst_base_src_loop (): /GstPipeline:raspiwatch-pipeline/GstRpiCamSrc:raspicam:
streaming stopped, reason error (-5)
Error received from element raspicam: Internal data stream error.
Debugging information: gstbasesrc.c(3055): gst_base_src_loop (): /GstPipeline:raspiwatch-pipeline/GstRpiCamSrc:raspicam:
streaming stopped, reason error (-5)
0:00:02.267737000 1069 0x1537320 INFO GST_ERROR_SYSTEM gstelement.c:2172:gst_element_message_full_with_details:<raspicam> posted error message: Internal data stream error.
0:00:02.272380000 1069 0x1537320 INFO splitmuxsink gstsplitmuxsink.c:1595:handle_mq_input:<splitmuxsink> Got Reference EOS. Finishing up
**
ERROR:gstsplitmuxsink.c:1380:handle_gathered_gop: assertion failed: (queued_gop_time >= 0)
thaytan commented
Hmm, looks like I forgot to set src->started = FALSE; in gstrpicamsrc.c:gst_rpi_cam_src_stop after cleanup - so it's not setting up the MMAL pieces on the 2nd run. Can you give that a try?
TimSchneider42 commented
That worked, I created a pull request