rtsp fails on connection (raspberry)

[SamuelDudley]

Testing last night on the webrtc-dev branch default settings pi3b+ with picam

rtsp pipeline was created OK rtsp pipeline fails on connection

Logs to come tonight

[fnoop]

rtsp crashes after an initial connection (see #9) but the system service restarts it. But initial connection and streaming should work just fine - i've tested it with gstreamer and vlc clients on multiple platforms. Need logs to see what might be the problem.

[SamuelDudley]

Yes, the failure in #9 is inline with what I was seeing last night, however failure was occuring on the first connect attempt. Attempting to stream to VLC on Android. Will provide logs tonight.

[SamuelDudley]

Example log of failure when connecting to a RTSP stream (picam with pi3b+)

Feb 25 12:38:54 maverick-raspberrylite python3[2271]: Starting visiond
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: Using log directory: /srv/maverick/var/log/vision
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,640 - Visiond - INFO - Starting maverick-visiond
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,644 - Visiond - INFO - pipeline_override is not set, auto-constructing pipeline
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,649 - Visiond - DEBUG - V4l2 device input: Camera 0:2
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,650 - Visiond - INFO - v4l2 device /dev/video0 is a camera, autoselecting
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,651 - Visiond - DEBUG - V4l2 device input: Camera 0:2
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,652 - Visiond - DEBUG - driver: bm2835 mmal
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,652 - Visiond - DEBUG - card: mmal service 16.1
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,653 - Visiond - DEBUG - Camera control: Brightness
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,653 - Visiond - DEBUG - Camera control: Contrast
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,654 - Visiond - DEBUG - Camera control: Saturation
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,655 - Visiond - DEBUG - Camera control: Red Balance
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,655 - Visiond - DEBUG - Camera control: Blue Balance
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,656 - Visiond - DEBUG - Camera control: Horizontal Flip
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,657 - Visiond - DEBUG - Camera control: Vertical Flip
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,657 - Visiond - DEBUG - Camera control: Power Line Frequency
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,658 - Visiond - DEBUG - Camera control: Sharpness
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,659 - Visiond - DEBUG - Camera control: Color Effects
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,659 - Visiond - DEBUG - Camera control: Rotate
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,660 - Visiond - DEBUG - Camera format: Planar YUV 4:2:0
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,661 - Visiond - DEBUG - Camera format: YUYV 4:2:2
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,661 - Visiond - DEBUG - Camera format: 24-bit RGB 8-8-8
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,662 - Visiond - DEBUG - Camera format: JFIF JPEG
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,662 - Visiond - DEBUG - Camera format: H.264
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,663 - Visiond - DEBUG - Camera format: Motion-JPEG
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,663 - Visiond - DEBUG - Camera format: YVYU 4:2:2
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,664 - Visiond - DEBUG - Camera format: VYUY 4:2:2
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,665 - Visiond - DEBUG - Camera format: UYVY 4:2:2
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,665 - Visiond - DEBUG - Camera format: Y/CbCr 4:2:0
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,666 - Visiond - DEBUG - Camera format: 24-bit BGR 8-8-8
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,666 - Visiond - DEBUG - Camera format: Planar YVU 4:2:0
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,667 - Visiond - DEBUG - Camera format: Y/CrCb 4:2:0
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,667 - Visiond - DEBUG - Camera format: 32-bit BGRA/X 8-8-8-8
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,669 - Visiond - DEBUG - Format: yuv : Planar YUV 4:2:0
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,670 - Visiond - DEBUG - Format: yuv : YUYV 4:2:2
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,671 - Visiond - DEBUG - Format: yuv : 24-bit RGB 8-8-8
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,672 - Visiond - DEBUG - Format: yuv : JFIF JPEG
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,672 - Visiond - DEBUG - Format: yuv : H.264
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,673 - Visiond - DEBUG - Format: yuv : Motion-JPEG
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,674 - Visiond - DEBUG - Format: yuv : YVYU 4:2:2
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,675 - Visiond - DEBUG - Format: yuv : VYUY 4:2:2
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,676 - Visiond - DEBUG - Format: yuv : UYVY 4:2:2
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,677 - Visiond - DEBUG - Format: yuv : Y/CbCr 4:2:0
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,678 - Visiond - DEBUG - Format: yuv : 24-bit BGR 8-8-8
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,679 - Visiond - DEBUG - Format: yuv : Planar YVU 4:2:0
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,680 - Visiond - DEBUG - Format: yuv : Y/CrCb 4:2:0
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,681 - Visiond - DEBUG - Format: yuv : 32-bit BGRA/X 8-8-8-8
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,682 - Visiond - INFO - Camera YUV stream available, using yuv stream
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,682 - Visiond - DEBUG - Using encoder: h264
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,683 - Visiond - DEBUG - Using pixelformat: YUY2
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,684 - Visiond - INFO - Creating stream object - camera:/dev/video0, stream:yuv, pixelformat:YFeb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,684 - Visiond - INFO - Attaching input 'v4l2': /dev/video0
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,717 - Visiond - INFO - Attaching stream 'yuv'
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,730 - Visiond - INFO - Attaching encoding 'h264'
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,731 - Visiond - INFO - Raspberry hardware encoder detected, using omxh264enc as h264 encoder Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,815 - Visiond - INFO - Attaching payload 'h264'
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,821 - Visiond - DEBUG - h264parse element created
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,830 - Visiond - DEBUG - Attaching h264pay to h264parse
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,831 - Visiond - INFO - Attaching output 'rtsp'
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,834 - Visiond - INFO - Overriding RTSPMediaFactory with constructed pipeline
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,838 - Visiond - INFO - RTSP stream running at rtsp://0.0.0.0:5600/video
Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,842 - Visiond - INFO - Pipeline: "v4l2-source /dev/video0 ! capsfilter 'video/x-raw, format=(Feb 25 12:38:54 maverick-raspberrylite python3[2271]: 2020-02-25 12:38:54,844 - Visiond - INFO - Starting camera stream
Feb 25 12:39:00 maverick-raspberrylite python3[2271]: 2020-02-25 12:39:00,323 - Visiond - INFO - Creating RTSP factory element: <GstRtsp.RTSPUrl object at 0x74b76ca8 (Feb 25 12:39:00 maverick-raspberrylite python3[2271]: 0:00:06.199923264  2271 0x73010830 WARN          v4l2bufferpool gstv4l2bufferpool.c:790:gst_v4l2_buffer_pool_starFeb 25 12:39:00 maverick-raspberrylite kernel: cma: cma_alloc: alloc failed, req-size: 338 pages, ret: -12
Feb 25 12:39:00 maverick-raspberrylite kernel: bcm2835-codec bcm2835-codec: dma_alloc_coherent of size 1384448 failed
Feb 25 12:39:00 maverick-raspberrylite python3[2271]: 0:00:06.649759647  2271 0x73010830 ERROR          v4l2allocator gstv4l2allocator.c:721:gst_v4l2_allocator_start:<Feb 25 12:39:00 maverick-raspberrylite python3[2271]: 0:00:06.650450518  2271 0x73010830 ERROR         v4l2bufferpool gstv4l2bufferpool.c:895:gst_v4l2_buffer_pool_starFeb 25 12:39:00 maverick-raspberrylite python3[2271]: 0:00:06.650938060  2271 0x73010830 ERROR             bufferpool gstbufferpool.c:564:gst_buffer_pool_set_active:<vFeb 25 12:39:00 maverick-raspberrylite python3[2271]: 0:00:06.651395863  2271 0x73010830 WARN           v4l2transform gstv4l2transform.c:947:gst_v4l2_transform_prepareFeb 25 12:39:00 maverick-raspberrylite python3[2271]: 0:00:06.651955591  2271 0x73010830 WARN           v4l2transform gstv4l2transform.c:947:gst_v4l2_transform_prepareFeb 25 12:39:00 maverick-raspberrylite kernel: cma: cma_alloc: alloc failed, req-size: 450 pages, ret: -12
Feb 25 12:39:00 maverick-raspberrylite kernel: bcm2835-codec bcm2835-codec: dma_alloc_coherent of size 1843200 failed
Feb 25 12:39:00 maverick-raspberrylite python3[2271]: 0:00:06.654087318  2271   0xf86120 WARN               rtspmedia rtsp-media.c:2722:default_handle_message: 0x73a06Feb 25 12:39:00 maverick-raspberrylite python3[2271]: failed to activate bufferpool)
Feb 25 12:39:00 maverick-raspberrylite python3[2271]: 0:00:06.654491997  2271   0xf85f20 WARN               rtspmedia rtsp-media.c:2991:wait_preroll: failed to prerollFeb 25 12:39:00 maverick-raspberrylite python3[2271]: 0:00:06.654626838  2271   0xf85f20 WARN               rtspmedia rtsp-media.c:3295:gst_rtsp_media_prepare: failed Feb 25 12:39:00 maverick-raspberrylite python3[2271]: 0:00:06.657468446  2271 0x73010830 WARN           basetransform gstbasetransform.c:2159:default_generate_output:<Feb 25 12:39:00 maverick-raspberrylite python3[2271]: gst_buffer_pool_set_active: assertion 'GST_IS_BUFFER_POOL (pool)' failed
Feb 25 12:39:00 maverick-raspberrylite python3[2271]: gst_object_unref: assertion '((GObject *) object)->ref_count > 0' failed
Feb 25 12:39:01 maverick-raspberrylite python3[2271]: 0:00:06.715333920  2271   0xf85f20 ERROR             rtspclient rtsp-client.c:1044:find_media: client 0xf8a898: cFeb 25 12:39:01 maverick-raspberrylite python3[2271]: 0:00:06.716298066  2271   0xf85f20 ERROR             rtspclient rtsp-client.c:2899:handle_describe_request: clienFeb 25 12:39:05 maverick-raspberrylite python3[2271]: 2020-02-25 12:39:05,723 - Visiond - INFO - Creating RTSP factory element: <GstRtsp.RTSPUrl object at 0x74b76ca8 (Feb 25 12:39:05 maverick-raspberrylite python3[2271]: gst_ghost_pad_new: assertion '!gst_pad_is_linked (target)' failed
Feb 25 12:39:05 maverick-raspberrylite python3[2271]: gst_pad_set_active: assertion 'GST_IS_PAD (pad)' failed
Feb 25 12:39:05 maverick-raspberrylite python3[2271]: gst_element_add_pad: assertion 'GST_IS_PAD (pad)' failed
Feb 25 12:39:05 maverick-raspberrylite python3[2271]: gst_rtsp_stream_new: assertion 'GST_IS_PAD (pad)' failed
Feb 25 12:39:05 maverick-raspberrylite python3[2271]: gst_rtsp_stream_set_multicast_iface: assertion 'GST_IS_RTSP_STREAM (stream)' failed
Feb 25 12:39:05 maverick-raspberrylite python3[2271]: gst_rtsp_stream_set_profiles: assertion 'GST_IS_RTSP_STREAM (stream)' failed
Feb 25 12:39:05 maverick-raspberrylite python3[2271]: gst_rtsp_stream_set_protocols: assertion 'GST_IS_RTSP_STREAM (stream)' failed
Feb 25 12:39:05 maverick-raspberrylite systemd[1]: maverick-visiond.service: Main process exited, code=killed, status=11/SEGV
Feb 25 12:39:05 maverick-raspberrylite systemd[1]: maverick-visiond.service: Failed with result 'signal'.

[SamuelDudley]

Looks like the pi is failing to allocate memory...

Feb 25 12:39:00 maverick-raspberrylite kernel: bcm2835-codec bcm2835-codec: dma_alloc_coherent of size 1384448 failed

adding cma=256M to /boot/cmdline.txt to define the heap to be 256MB resolves the issue

[fnoop]

I've never seen that before on any rpi i've had, very odd. Have you updated the firmware recently? I can't remember if that still needs an rpi-update run. What is the cpu/gpu mem split set to? (maverick info)

[fnoop]

Without setting cma=256M in cmdline.txt, what is it set to?

[dev] [mav@maverick-raspberry ~/code/vid/gstwebrtc-demos/sendonly]$ cat /proc/meminfo  |grep Cma
CmaTotal:         262144 kB
CmaFree:           96416 kB

[SamuelDudley]

with cma=256M in cmdline.txt

C/G is 896/128

CmaTotal:         262144 kB
CmaFree:          259960 kB

[SamuelDudley]

without cma=256M

CmaTotal:           8192 kB
CmaFree:            6028 kB

note: same split in maverick info C/G is 896/128

[fnoop]

How odd. My rpi4 with 2gb has 256 already set. Wonder if it's set dynamically according to the model.

[SamuelDudley]

note this is brand new pi3b+ fresh out the box... I'll run rpi-update and see if there is any change

[SamuelDudley]

after rpi-update and a reboot there is no change:

CmaTotal:           8192 kB
CmaFree:            6016 kB

clearly visiond fails with this config.

[SamuelDudley]

At a minimum we can look for the issue and let the user know. Otherwise we can set the value in cmdline.txt. Unsure what the best option here is.

[fnoop]

Very odd. i developed visiond rtsp on a pi3b. I'll look further into it.

[SamuelDudley]

For what it is worth I was reading this issue when I found the cmdline.txt fix https://github.com/raspberrypi/linux/issues/3171#issuecomment-524213863

# For more options and information see
# http://rpf.io/configtxt
# Some settings may impact device functionality. See link above for details

# uncomment if you get no picture on HDMI for a default "safe" mode
#hdmi_safe=1

# uncomment this if your display has a black border of unused pixels visible
# and your display can output without overscan
#disable_overscan=1

# uncomment the following to adjust overscan. Use positive numbers if console
# goes off screen, and negative if there is too much border
#overscan_left=16
#overscan_right=16
#overscan_top=16
#overscan_bottom=16

# uncomment to force a console size. By default it will be display's size minus
# overscan.
#framebuffer_width=1280
#framebuffer_height=720

# uncomment if hdmi display is not detected and composite is being output
#hdmi_force_hotplug=1

# uncomment to force a specific HDMI mode (this will force VGA)
#hdmi_group=1
#hdmi_mode=1

# uncomment to force a HDMI mode rather than DVI. This can make audio work in
# DMT (computer monitor) modes
#hdmi_drive=2

# uncomment to increase signal to HDMI, if you have interference, blanking, or
# no display
#config_hdmi_boost=4

# uncomment for composite PAL
#sdtv_mode=2

#uncomment to overclock the arm. 700 MHz is the default.
#arm_freq=800

# Uncomment some or all of these to enable the optional hardware interfaces
dtparam=i2c_arm=on
#dtparam=i2s=on
dtparam=spi=on

# Uncomment this to enable infrared communication.
#dtoverlay=gpio-ir,gpio_pin=17
#dtoverlay=gpio-ir-tx,gpio_pin=18

# Additional overlays and parameters are documented /boot/overlays/README

# Enable audio (loads snd_bcm2835)
dtparam=audio=on

[pi4]
# Enable DRM VC4 V3D driver on top of the dispmanx display stack
dtoverlay=vc4-fkms-v3d
max_framebuffers=2

possible that as dtoverlay=vc4-fkms-v3d is under [pi4] now the memory is no longer automatically assigned on other pi's?

[SamuelDudley]

perhaps its related to the lite build over the full desktop build?

[fnoop]

v.interesting. That comment says the default for pi4 is 256, pi0-3 is 8. Could you try setting to 32 or 64, and see if that works?

[SamuelDudley]

working with cma=32M

CmaTotal:          32768 kB
CmaFree:           30604 kB

[fnoop]

Thanks, hopefully there's some way of fixing this without having to set cma. Will look into it.