search

scottlamb / moonfire-nvr

Moonfire NVR, a security camera network video recorder
Other
1.26k stars 138 forks source link

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

Closed IronOxidizer closed 2 years ago

IronOxidizer commented 2 years ago

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:

  1. Add a camera
  2. Test camera (no errors)
  3. Run nvr start
  4. 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):

Camera (please complete the following information):

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

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

Desktop (please complete the following information):

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.

scottlamb commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

I'd be glad to help however I can

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

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 commented 2 years ago

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

scottlamb commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

Sent it to your email

scottlamb commented 2 years ago

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:

IronOxidizer commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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

IronOxidizer commented 2 years ago

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 commented 2 years ago

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

scottlamb commented 2 years ago

I filed a fresh issue on that, #217.