Unable to parse stream 0: bad clockrate in rtpmap #213

IronOxidizer · 2022-04-02T23:07:23Z

Describe the bug
No video is being written and no live view available. 0 bytes used as reported in nvr-config. /media/nvr/sample is also empty other than the meta file. Logs shows hundreds of instances of Unable to parse stream 0: bad clockrate in rtpmap followed by a stacktrace

This is a regression since this setup with these cameras were previously working flawlessly 1 month ago. It was using an earlier release of moonfire (docker ~April 2021).

To Reproduce
Steps to reproduce the behavior:

Add a camera
Test camera (no errors)
Run nvr start
No records in the webview and no live view

Expected behavior
At least some bytes should be written to indicate that moonfire is ingesting the stream.

Server (please complete the following information):

docker ps

CONTAINER ID   IMAGE     COMMAND   CREATED   STATUS    PORTS     NAMES

docker images

REPOSITORY               TAG       IMAGE ID       CREATED        SIZE
scottlamb/moonfire-nvr   v0.7.2    bb513b601e64   2 weeks ago    542MB
hello-world              latest    1ec996c686eb   6 months ago   4.85kB

log.txt

Camera (please complete the following information):

Manufacturer, Model, Firmware (according to the camera lol):

H264, 53X13_32M, V5.00.R01.00023651.10010.249501..ONVIF 2.4 (3 of these)
IPCAM, C9F0SeZ3N0PbL0, firmware V13.1.48.16.3-20200320
NVT, null, null

They're just cheap onvif cams from aliexpress and thrift stores (dw, they're airgapped)

Desktop (please complete the following information):

OS: Linux
Browser Firefox
Version 95

Additional context
My hard drive recently failed and the root partition was located on the drive so I had to reinstall. If I were to guess, the regression is from dropping ffmpeg. I'll try the last release that used ffmpeg and report back here, though that'll probably have to wait till next week.

The text was updated successfully, but these errors were encountered:

scottlamb · 2022-04-03T16:08:35Z

Since ~April 2021, I switched from ffmpeg to my own pure-Rust RTSP library, Retina. See #37. [Edit: oh, I missed your last paragraph. I see now you already knew that!] I'm happy I made the switch, but we're still going through some growing pains with Retina bugs and camera incompatibilities.

In this case, your camera's rtpmap parameter is "96 H264/90000 ". I quoted the grammar here in Retina code. Looks like that trailing space is not supposed to be there; the camera is broken. But it seems easy enough to work around by trimming the string first.

scottlamb · 2022-04-03T18:56:03Z

Another small thing I'd like to change: the error message here:

https://github.com/scottlamb/retina/blob/76d5d883fa3fa293a5567c4024923500c6378053/src/client/parse.rs#L439

In hindsight, I don't like that it gives the Debug output of a sdp_types::Media rather than the original raw SDP bytes given by the camera. When I make fixes like this, I like to add a testdata file with the actual data given by the camera, which would be more telling if there were a bug in the sdp_types layer. It'd be better if that data appeared in the logs.

If you don't mind, I might bug you later to run a (to-be-written) Retina command to grab the actual SDP bytes for that unit test.

IronOxidizer · 2022-04-03T20:47:53Z

I'd be glad to help however I can

scottlamb/moonfire-nvr#213 (comment)

scottlamb · 2022-04-04T22:49:06Z

$ git clone https://github.com/scottlamb/retina.git
$ cd retina
$ cargo run --example client -- info --print-sdp --url 'URL' --username 'USER' --password 'PASS'

IronOxidizer · 2022-04-05T00:55:38Z

Cams 1, 2, and 3:

E20220404 20:52:36.994 main client] Fatal: [192.168.1.64:49098(me)->192.168.1.67:554@2022-04-04T20:52:36, 0@2022-04-04T20:52:36] Ok response to DESCRIBE CSeq=1: Unable to parse stream 0: bad clockrate in rtpmap
raw SDP: "v=0\r
o=- 38990265062388 38990265062388 IN IP4 192.168.1.67\r
s=RTSP Session\r
c=IN IP4 192.168.1.67\r
t=0 0\r
a=control:*\r
a=range:npt=0-\r
m=video 0 RTP/AVP 96\r
a=rtpmap:96 H264/90000 \r
a=range:npt=0-\r
a=framerate:0S\r
a=fmtp:96 profile-level-id=4d0020; packetization-mode=1; sprop-parameter-sets=J00AII1qBQB5oQAAAwABAAADACiE,KO48gA==\r
a=Media_header:MEDIAINFO=494D4B48010100000400010000000000000000000000000000000000000000000000000000000000;\r
a=framerate:25\r
a=control:trackID=1\r
"

Cam 4:

W20220404 20:53:45.863 main retina::codec::h264] Ignoring bad H.264 format-specific-params "packetization-mode=1;profile-level-id=000001;sprop-parameter-sets=AAAAAUdNAB+ZsBQBboQAAA+gAAF3AhA=,AAAAAUjqQ8g=": only SPS and PPS expected in parameter sets
SDP:
v=0
o=- 38990265062388 38990265062388 IN IP4 192.168.1.70
s=10
c=IN IP4 0.0.0.0
t=0 0
a=control:*
a=range:npt=0-
m=video 0 RTP/AVP 96
a=control:trackID=0
a=rtpmap:96 H264/90000
a=range:npt=0-
a=framerate:0S
a=fmtp:96 packetization-mode=1;profile-level-id=000001;sprop-parameter-sets=AAAAAUdNAB+ZsBQBboQAAA+gAAF3AhA=,AAAAAUjqQ8g=
a=framesize:96 1280-720
m=audio 0 RTP/AVP 8
a=control:trackID=1
a=rtpmap:8 PCMA/8000/1
a=ptime:20
a=fmtp:8 packetization-mode=1



I20220404 20:53:45.865 main client] Done

Cam 5:

E20220404 20:54:30.987 main client] Fatal: [192.168.1.64:35568(me)->192.168.1.71:554@2022-04-04T20:54:30, 0@2022-04-04T20:54:30] Ok response to DESCRIBE CSeq=1: Unable to parse stream 0: bad clockrate in rtpmap
raw SDP: "v=0\r
o=- 38990265062388 38990265062388 IN IP4 192.168.1.71\r
s=RTSP Session\r
c=IN IP4 192.168.1.71\r
t=0 0\r
a=control:*\r
a=range:npt=0-\r
m=video 0 RTP/AVP 96\r
a=rtpmap:96 H264/90000 \r
a=range:npt=0-\r
a=framerate:0S\r
a=fmtp:96 profile-level-id=4d0029; packetization-mode=1; sprop-parameter-sets=J00AKY1qB4AiflhAAAADAEAAAAYh,KO4Fcg==\r
a=framerate:25\r
a=control:trackID=3\r
m=audio 0 RTP/AVP 8\r
a=control:trackID=4\r
"

IronOxidizer · 2022-04-05T01:19:00Z

Just confirmed that my setup works without any issues on moonfire 0.6.3.

scottlamb/moonfire-nvr#213

scottlamb · 2022-04-05T02:37:11Z

If you pull the latest retina, does cargo run --example client -- mp4 ... produce a valid .mp4 file? This error should be fixed anyway. I haven't made a Retina release or updated Moonfire NVR to use it yet.

IronOxidizer · 2022-04-05T03:06:11Z

It does for cams 1, 2, 3, and 4.

Cam 5 throws the following error:

I20220404 23:05:35.801 main client::mp4] Using h264 video stream
I20220404 23:05:35.814 main client::mp4] Ignoring pcma audio stream because it can't be placed into a .mp4 file without transcoding
I20220404 23:05:35.814 main client::mp4] No suitable audio stream found
E20220404 23:05:35.894 main client] Fatal: [192.168.1.64:35594(me)->192.168.1.71:554@2022-04-04T23:05:35, 956@2022-04-04T23:05:35] Received interleaved data on unassigned channel 2

scottlamb · 2022-04-05T03:47:42Z

Received interleaved data on unassigned channel 2

Huh. I wonder if it's sending audio on the channel (even though it wasn't requested) or what.

Does that error happen if it's been at least a couple minutes since anything has talked to the camera? Some live555-based cameras have a problem where they keep sending data for stale sessions on a particular file descriptor after it's been closed. If the fd reassigned to another connection, they just send the old session's data on the new connection. Their sessions time out after about 65 seconds.

Do you mind sharing a couple packet captures—one with Retina failing, one with ffmpeg succeeding? ffmpeg should run with a command like this:

$ ffmpeg -y -fflags nobuffer -rtsp_transport tcp -allowed_media_types video -t 5 -i 'rtsp://user:pass@...' -c copy ffmpeg.mp4

and I typically just grab packet captures with tcpdump in another terminal:

$ sudo tcpdump -Uw blah.pcap -ni INTERFACE 'ip host 192.168.1.71'
...
^C when done

If you don't want to share your MACs, camera credentials, etc. with the world, you can send it to me via email (attachment, download link, whatever) rather than on the public issue tracker.

IronOxidizer · 2022-04-05T19:48:04Z

Sent it to your email

scottlamb · 2022-04-05T21:56:16Z

Thank you. From looking at that, it looks like the stuff on RTSP interleaved channel 2 (e.g. packet 288 in ffmpeg-5.pcap) is audio. Wireshark doesn't decode it because (like Retina) it wasn't expecting something on an unassigned RTSP channel, but if you compare to the RFC: looks like RTP, payload type 8 = pcma matches the audio stream in the SDP, ascending sequence numbers. And the timestamps 160 units apart with 160 bytes of payload makes sense for 8 bit per sample uncompressed audio.

So the question is: what should we do about it? I'm not sure, but I have a couple ideas:

prevent: I guess we could ask for the audio stream, and then it wouldn't be unexpected anymore. (Hopefully it comes in on the channel we ask for then? who knows!) We don't need the audio now, but if there's sufficient bandwidth between the camera and NVR it won't do any harm. I want to add real audio support (audio support #34), and also audio gives timing information that seems more reliable than the RTP timestamps on the video stream for many of these crappy camera models. Audio mode (actually record, request and use for timing only, request and discard, don't request, etc.) can be controllable with a Moonfire configuration option.
handle: ffmpeg seems to ignore packets on unassigned channels. Moonfire/Retina has logic that thinks they're due to the live555 stale session bug and drops the connection and waits out a stale session. ffmpeg's behavior seems better for your camera. We could add a knob to choose, and/or support autodetecting based on how the server names itself, although this server...doesn't name itself through either a SDP-level a:tool or a RTSP-level Server: header, and some of the live555 servers also don't name themselves well.

IronOxidizer · 2022-04-05T22:20:27Z

ffmpeg seems to ignore packets on unassigned channels.

This seems like the more robust approach. With the countless amount of RTSP implementations out there, I feel like this won't be the last time we'll see random packets on unassigned channels. Ignoring it seems like the safest bet to support as much hardware as possible in the future.

scottlamb · 2022-04-05T22:40:36Z

It's still surprising to me how shoddy these RTSP implementations seem to be. In contrast, even in the cheapest devices, the HTTP implementations are basically fine.

scottlamb/moonfire-nvr#213 (comment)

scottlamb · 2022-04-08T22:39:17Z

If you git pull Retina again, it will hopefully work now, unless there's another bug waiting...

I'll likely make a Moonfire release with this change (and a few other things) next week.

IronOxidizer · 2022-04-09T17:08:58Z

Seems like it worked. Thanks! Looking forward to the next release.

IronOxidizer · 2022-04-09T19:20:10Z

For the most part it seems to be working, though after a few minutes (or even seconds, it's inconsistent) I get the following error. Seems like an issue parsing a keyframe since I only get it after a large byte video frame.

I20220409 15:15:12.382 main client::mp4] Using h264 video stream
I20220409 15:15:12.389 main client::mp4] Ignoring pcma audio stream because it c                                                                                                                                                             an't be placed into a .mp4 file without transcoding
I20220409 15:15:12.389 main client::mp4] No suitable audio stream found
W20220409 15:15:12.414 main retina::client] Ignoring data on unassigned RTSP int                                                                                                                                                             erleaved data channel 2. This is the first such message. Following messages will                                                                                                                                                              be logged at trace priority only.

conn: 192.168.1.64:33994(me)->192.168.1.71:554@2022-04-09T15:15:12
msg: 954@2022-04-09T15:15:12
data: Length: 172 (0xac) bytes
0000:   80 88 00 00  1a 91 98 f0  00 00 00 01  d4 d4 d4 d4   ................
0010:   d4 d7 d7 d7  d7 d4 d4 d4  d5 d5 d5 d5  d5 d5 d5 d5   ................
0020:   d5 d5 d4 d4  d4 d4 d4 d4  d5 d5 d4 d4  d4 d7 d7 d7   ................
0030:   d7 d4 d4 d5  d5 d5 55 55  55 55 d5 55  55 d5 d5 d5   ......UUUU.UU...
0040:   d4 d5 d4 d4  d4 d4 d4 d4  d4 d7 d4 d7  d4 d5 d4 d5   ................
0050:   d5 d4 d4 d4  d4 d4 d4 d4  d5 d4 d4 d5  d4 d4 d4 d4   ................
0060:   d5 d5 d5 d5  d5 d4 d4 d7  d7 d7 d7 d4  d4 d4 d5 d5   ................
0070:   d5 d5 d5 d5  d5 d5 d5 d5  d5 d4 d4 d4  d4 d4 d5 d4   ................

...44 (0x2c) bytes not shown...
526865204 (mod-2^32: 526865204), npt 0.000: 250698-byte video frame
526872704 (mod-2^32: 526872704), npt 0.083: 1606-byte video frame
526880204 (mod-2^32: 526880204), npt 0.167: 1888-byte video frame
526887704 (mod-2^32: 526887704), npt 0.250: 1675-byte video frame
526895204 (mod-2^32: 526895204), npt 0.333: 2272-byte video frame
526902704 (mod-2^32: 526902704), npt 0.417: 606-byte video frame
526910204 (mod-2^32: 526910204), npt 0.500: 2057-byte video frame
526917704 (mod-2^32: 526917704), npt 0.583: 1872-byte video frame
526925204 (mod-2^32: 526925204), npt 0.667: 1787-byte video frame
526932704 (mod-2^32: 526932704), npt 0.750: 2730-byte video frame
526940204 (mod-2^32: 526940204), npt 0.833: 4246-byte video frame
526947704 (mod-2^32: 526947704), npt 0.917: 1768-byte video frame
526955204 (mod-2^32: 526955204), npt 1.000: 316962-byte video frame
E20220409 15:15:13.815 main client] Fatal: Error processing video frame starting                                                                                                                                                              with 287984@2022-04-09T15:15:13 ch=0
caused by: video parameters change unimplemented.
old: VideoParameters {
    rfc6381_codec: "avc1.4D0029",
    pixel_dimensions: (
        1920,
        1080,
    ),
    pixel_aspect_ratio: None,
    frame_rate: Some(
        (
            2,
            24,
        ),
    ),
    extra_data: Length: 37 (0x25) bytes
    0000:   01 4d 00 29  ff e1 00 15  27 4d 00 29  8d 6a 07 80   .M.)....'M.).j.                                                                                                                                                             .
    0010:   22 7e 58 40  00 00 03 00  40 00 00 06  21 01 00 05   "~X@....@...!..                                                                                                                                                             .
    0020:   28 ee 03 9c  80                                      (....
    ,
}
new: VideoParameters {
    rfc6381_codec: "avc1.4D0029",
    pixel_dimensions: (
        1920,
        1080,
    ),
    pixel_aspect_ratio: None,
    frame_rate: Some(
        (
            2,
            24,
        ),
    ),
    extra_data: Length: 36 (0x24) bytes
    0000:   01 4d 00 29  ff e1 00 15  27 4d 00 29  8d 6a 07 80   .M.)....'M.).j.                                                                                                                                                             .
    0010:   22 7e 58 40  00 00 03 00  40 00 00 06  21 01 00 04   "~X@....@...!..                                                                                                                                                             .
    0020:   28 ee 05 72                                          (..r
    ,
}

scottlamb · 2022-04-09T20:57:37Z

Thanks. I'll decode those extra_data bytes later and see what changed.

scottlamb · 2022-04-10T05:16:04Z

I filed a fresh issue on that, #217.

This alone improves interop and diagnostics, as noted in Retina's release notes. We also now give the camera name to the session group (for improved logging of TEARDOWN operations) and expose the RTSP server's "tool" attribute in debug logs and the config UI's "Test" button. Fixes #209 Fixes #213

scottlamb added a commit to scottlamb/retina that referenced this issue Apr 4, 2022

better debug output on SDP parse failure

443de81

scottlamb/moonfire-nvr#213 (comment)

scottlamb added a commit to scottlamb/retina that referenced this issue Apr 5, 2022

ignore trailing spaces in rtpmap attribute

31080f3

scottlamb/moonfire-nvr#213

scottlamb added a commit to scottlamb/retina that referenced this issue Apr 8, 2022

support ignoring msgs on unassigned RTSP channels

7cbe392

scottlamb/moonfire-nvr#213 (comment)

IronOxidizer closed this as completed Apr 9, 2022

scottlamb mentioned this issue Apr 10, 2022

seamless mid-stream video parameter changes #217

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Unable to parse stream 0: bad clockrate in rtpmap #213

Unable to parse stream 0: bad clockrate in rtpmap #213

IronOxidizer commented Apr 2, 2022 •

edited

Loading

scottlamb commented Apr 3, 2022 •

edited

Loading

scottlamb commented Apr 3, 2022

IronOxidizer commented Apr 3, 2022

scottlamb commented Apr 4, 2022

IronOxidizer commented Apr 5, 2022

IronOxidizer commented Apr 5, 2022

scottlamb commented Apr 5, 2022

IronOxidizer commented Apr 5, 2022

scottlamb commented Apr 5, 2022

IronOxidizer commented Apr 5, 2022

scottlamb commented Apr 5, 2022 •

edited

Loading

IronOxidizer commented Apr 5, 2022 •

edited

Loading

scottlamb commented Apr 5, 2022

scottlamb commented Apr 8, 2022

IronOxidizer commented Apr 9, 2022

IronOxidizer commented Apr 9, 2022

scottlamb commented Apr 9, 2022

scottlamb commented Apr 10, 2022

Unable to parse stream 0: bad clockrate in rtpmap #213

Unable to parse stream 0: bad clockrate in rtpmap #213

Comments

IronOxidizer commented Apr 2, 2022 • edited Loading

scottlamb commented Apr 3, 2022 • edited Loading

scottlamb commented Apr 3, 2022

IronOxidizer commented Apr 3, 2022

scottlamb commented Apr 4, 2022

IronOxidizer commented Apr 5, 2022

IronOxidizer commented Apr 5, 2022

scottlamb commented Apr 5, 2022

IronOxidizer commented Apr 5, 2022

scottlamb commented Apr 5, 2022

IronOxidizer commented Apr 5, 2022

scottlamb commented Apr 5, 2022 • edited Loading

IronOxidizer commented Apr 5, 2022 • edited Loading

scottlamb commented Apr 5, 2022

scottlamb commented Apr 8, 2022

IronOxidizer commented Apr 9, 2022

IronOxidizer commented Apr 9, 2022

scottlamb commented Apr 9, 2022

scottlamb commented Apr 10, 2022

IronOxidizer commented Apr 2, 2022 •

edited

Loading

scottlamb commented Apr 3, 2022 •

edited

Loading

scottlamb commented Apr 5, 2022 •

edited

Loading

IronOxidizer commented Apr 5, 2022 •

edited

Loading