Implement fake seek for VLC

QuantumEntangledAndy commented 1 year ago

VLC seems to be peoples prefered media player

Went to look into why it plays so jittering on VLC but is ok in ffmpeg etc. Came back with these things:

VLC is not a low latency player, you need to change some setting and it's still not perfect
VLC does not seem to respect live NON SEEKABLE streams

To test things I printed the time stamps as being sent from neolink and watched the time stamps comming in on VLC what was observed was that by the time VLC has finished starting up neolink is now pushing data about 5s ahead of VLC's "now". VLC reports that buffers are "way too early" and starts adding zeros in.

What VLC seems to do is connect to the stream and then request a SEEK back to zero. Well neolink streams aren't seekable resulting in the issues we see.

To address this I added a fake SEEK what it does is adjust the clients buffer start time such that new buffers are now at the requested seek time (even though really its just the same new buffers just stamped differently)

Update:

To address this even further additional changes have been made:

maintain a buffer for local seeking. Rather that always updating to live on any seek request we now see if we can seek within a local buffer of about 3 IFrame + their associated Pframes and audio
we now only push buffers onto the gatreamer pipeline if the clock matches the buffer. This really improves the connect speed of vlc and ffmpeg
~~If a client gets too far behind the stream then seek them back to live. This should help with keeping us closer to the live picture from the camera.~~ Edit: Removed due to loop issues during stream errors

Possible related issues: #37 #38 #48 #56

Veuchez commented 1 year ago

With this latest version I don't get any errors, I see much better, but I still have the video stream slightly jerky, both in mainstream and substream... the video stream is not yet as smooth as in Reolink streaming.

QuantumEntangledAndy commented 1 year ago

@Veuchez Could you try once more with the latest from here. I've been working hard to iron out all buffering issues in the pipeline such that vlc will just work (without config changes)

My vlc now opens almost instantly with smooth video. I would like some outside confirmation before I merge though.

test build downloads

QuantumEntangledAndy commented 1 year ago

P.s. if not already put the jitterbuffer back to the default 5000 and clock sync method to default in the vlc config. That should allow vlc to buffer the packets on its end and play them smoothly

Veuchez commented 1 year ago

With today's "version" we are almost perfect on VLC, congratulations. There are still a few small shots every now and then. On Frigate, on the other hand, I still see everything jerky.

QuantumEntangledAndy commented 1 year ago

I see. Looks like I'm going to need to get a copy of frigate myself and see what's up.

My laptop however is in for repair for the week so will have to wait until after that before I can do any serious coding again.

Checksum commented 1 year ago

Sorry been very busy at work. I did a bit of testing last week with this PR and did see some improvement. But reading your most recent fix and your comment on the VLC settings, I'll give it another go today.

Checksum commented 1 year ago

The latest commit makes streaming MUCH better. The stream is now playable in VLC and doesn't skip much. After the initial delay of 3-5s buffering, VLC doesn't seem to drop that many frames.

Also, tested with scrypted. My setup is Reolink Argus PT -> Neolink -> Scrypted -> Homekit and the stream is entirely usable. Previously I use to be able to see a max of 2 seconds every 15-20 seconds. This makes things a million times better.

Great work on figuring this out @QuantumEntangledAndy ! I'll keep an eye overnight to see, but I am almost certain looking at the logs that it should be fine over a period of time.

Checksum commented 1 year ago

So had the neolink docker container running overnight. The stream doesn't work and I see the following in the logs:

[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::factory] Building H264 Pipeline
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::factory] No clock
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender] PTS: 33.336ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender] PTS: 99.999ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender] PTS: 166.67ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender] PTS: 233.337ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender] PTS: 300.001ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender] PTS: 366.666ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender] PTS: 433.335ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::factory] Send seek H264: 0
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::factory]   - Sent seek H264: true
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender] PTS: 499.999ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender]   - runtime: 112084.003670808s
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender]   - buftime: 566.668ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender] PTS: 566.668ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender]   - runtime: 112084.004924639s
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender]   - buftime: 633.336ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender] PTS: 633.336ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender]   - runtime: 112084.005280374s
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender]   - buftime: 700.002ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender] PTS: 700.002ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender]   - runtime: 112084.006116787s
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender]   - buftime: 766.666ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender] PTS: 766.666ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender]   - runtime: 112084.006300117s
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender]   - buftime: 833.335ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::sender] PTS: 833.335ms
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::factory] Send seek H264: 0
[2023-04-27T09:48:56Z DEBUG neolink::rtsp::gst::factory]   - Sent seek H264: true

Restarting the container fixes it. I imagine the No clock message is probably the most interesting?

QuantumEntangledAndy commented 1 year ago

No clock is actually normal. The steam starts in a no clock state until it gets into the play state. It's the time when we send buffers for format identification rather than an actual stream.

Is there anything else interesting in the log?

Veuchez commented 1 year ago

It happens to me too. neolink works but the stream is not visible.

Checksum commented 1 year ago

I just realised I didn't have the correct logging levels set for neolink 🤦🏽‍♂️ I'll give it another go today. In case it helps, this is the VLC log:

Checksum commented 1 year ago

Some trace info from neolink. So the behaviour I noticed is that if I connect to neolink immediately after restarting, it works. But trying after about 10 mins doesn't succeed. I don't think it's got anything to do with the amount of time it waits for in between client requests.

https://gist.github.com/Checksum/2433b385d2830c16216fd92a73a0b5df

QuantumEntangledAndy commented 1 year ago

The PTS log stops but we are still getting frames. It seems to happen after a jump to live. I'll have to check my logic there. But maybe will wait a week until I get my laptop back.

QuantumEntangledAndy commented 1 year ago

Ive reworked my buffer code again. It should now handle jump to live better. Could you test once more?

Checksum commented 1 year ago

Ive reworked my buffer code again. It should now handle jump to live better. Could you test once more?

Thanks! Gave it a quick test. First time I connected with VLC, stream played with ~4s delay. Quality was steady. Then disconnect VLC and tried again, and no stream the second time around. Tried stopping/reconnecting VLC a few more times and noticed something bizzare: the stream only plays every other time (1, 3, 5, ....). I found this weird, so restarted neolink and tried again and the same behaviour!

Didn't have access to my PC to capture logs, will try to do that tomorrow.

QuantumEntangledAndy commented 1 year ago

Alright yet another build on the way. I think VLC was complaining about the buffers sent while in the preparing state. I've reworked those to only send prepration buffers up to the expected live point.

I am hoping that will do it for VLC. VLC seems to be very picky about its stream data. I will have a go at Frigate maybe it will also help. Does anyone have an example config? I'm trying to cobble one together from the docs but an actual in production one would help to make sure it works

Checksum commented 1 year ago

Alright yet another build on the way. I think VLC was complaining about the buffers sent while in the preparing state. I've reworked those to only send prepration buffers up to the expected live point.

I am hoping that will do it for VLC. VLC seems to be very picky about its stream data. I will have a go at Frigate maybe it will also help. Does anyone have an example config? I'm trying to cobble one together from the docs but an actual in production one would help to make sure it works

Just tried this out: panic and crashed unfortunately. Logs here - https://gist.github.com/Checksum/2433b385d2830c16216fd92a73a0b5df

QuantumEntangledAndy commented 1 year ago

Ah this again. This happened on one of my tests but I couldn't replicate it. I need a full trace back to see which subtraction is failing.

QuantumEntangledAndy commented 1 year ago

If you can get it reliably please add this environment variable RUST_BACKTRACE=1

Checksum commented 1 year ago

If you can get it reliably please add this environment variable RUST_BACKTRACE=1

Was trying that as I saw your comment :) Here is the stack trace:

neolink  | [2023-05-01T07:27:56Z DEBUG neolink::rtsp::gst::sender] Outside buffer jumping to live: 3.608896s < 5.655133567s < 5.608895s
neolink  | thread 'tokio-runtime-worker' panicked at 'overflow when subtracting durations', library/core/src/time.rs:936:31
neolink  | stack backtrace:
neolink  |    0: rust_begin_unwind
neolink  |              at ./rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/std/src/panicking.rs:579:5
neolink  |    1: core::panicking::panic_fmt
neolink  |              at ./rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/panicking.rs:64:14
neolink  |    2: core::panicking::panic_display
neolink  |              at ./rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/panicking.rs:147:5
neolink  |    3: core::panicking::panic_str
neolink  |              at ./rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/panicking.rs:131:5
neolink  |    4: core::option::expect_failed
neolink  |              at ./rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/option.rs:2045:5
neolink  |    5: core::option::Option<T>::expect
neolink  |              at ./rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/option.rs:905:21
neolink  |    6: <core::time::Duration as core::ops::arith::Sub>::sub
neolink  |              at ./rustc/84c898d65adf2f39a5a98507f1fe0ce10a2b8dbc/library/core/src/time.rs:936:31
neolink  |    7: neolink::rtsp::gst::sender::NeoMediaSender::jump_to_live::{{closure}}
neolink  |    8: neolink::rtsp::gst::sender::NeoMediaSenders::handle_buffer::{{closure}}
neolink  |    9: <neolink::rtsp::gst::factory::NeoMediaFactoryImpl as core::default::Default>::default::{{closure}}
neolink  |   10: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
neolink  |   11: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
neolink  |   12: tokio::runtime::task::harness::Harness<T,S>::poll
neolink  |   13: tokio::runtime::scheduler::multi_thread::worker::Context::run_task
neolink  |   14: tokio::runtime::scheduler::multi_thread::worker::Context::run
neolink  |   15: tokio::macros::scoped_tls::ScopedKey<T>::set
neolink  |   16: tokio::runtime::scheduler::multi_thread::worker::run
neolink  |   17: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
neolink  |   18: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
neolink  |   19: tokio::runtime::task::harness::Harness<T,S>::poll
neolink  |   20: tokio::runtime::blocking::pool::Inner::run
neolink  | note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
neolink  | Error: task 5 panicked

QuantumEntangledAndy commented 1 year ago

Thanks next build should fix this

QuantumEntangledAndy commented 1 year ago

Ok should work now, I had a few short tests in frigate too and everything seemed ok in the logs

Checksum commented 1 year ago

Can't see the new docker tag - looks like a few CI steps failed. Will try again when the image is published.

QuantumEntangledAndy commented 1 year ago

Yes the GitHub runners seem to be having internet connectivity issues. It keeps failing at the steps where it downloads the dependencies. Usually just needs a rerun.

QuantumEntangledAndy commented 1 year ago

Ok built

docker pull quantumentangledandy/neolink:fix-vlc_seek

Checksum commented 1 year ago

Can't view the stream in VLC :( Logs attached.

neolink.log

QuantumEntangledAndy commented 1 year ago

Yeah just fixed that, bugs always seem to creep in at the last minute. This one was made while trying to fix something I noticed in frigate

QuantumEntangledAndy commented 1 year ago

Should be ready again

docker pull quantumentangledandy/neolink:fix-vlc_seek

QuantumEntangledAndy commented 1 year ago

When a stream is not yet ready (camera connecting) neolink puts up a dummy stream with static and the message stream not ready.

I noticed that frigate would not refresh that stream automatically once the real stream becomes avaliable so I added something in neolink to drop all current sessions when the stream is avaliable.

This seems to be working to force frigate to reconnect to the real stream.

Checksum commented 1 year ago

No stream at all in VLC unfortunately.

QuantumEntangledAndy commented 1 year ago

What sort of issue is it? Any logs or anything? I can confirm it runs on metal with my vlc etc

Checksum commented 1 year ago

Just don't see any video window in VLC. Not even a black video. Have attached both logs

VLC Debug Log (3.0.18 Vetinari).txt neolink.log

QuantumEntangledAndy commented 1 year ago

Seems to be an issue with the docker. It keeps reporting media not prepared for me though docker (but same code base works on metal). This may mean that the gstreamer needs a version bump. I'll try and build the docker image locally and maybe update it to bullseye

QuantumEntangledAndy commented 1 year ago

Your log is a bit different then I expected. Do you usually have lines along the way of

: 3.608899s < 9.86991296s < 5.608897s

The first and last of these are the time stamps from the camera. Which are low since mine usually start at 10000 which is what is stopping us from jumping to live as we cannot set the start_time to a negative value.

Also is there anything in your full log about recieving I/PFrames? I cannot seem to see any of those

QuantumEntangledAndy commented 1 year ago

Whats happening here:

: 3.608899s < 9.86991296s < 5.608897s

is that the camera has given us data from 3s to 5s but we want to play at 9s. But there is no data at 9s. The current solution is to shift the start time backwards such that when asking for data at 9s we actually get data at 4s.

But this fails when the buffers starts so close to zero because of the use of unsigned integers (no negatives allowed).

Next build should address this by allowing the start time to go negative

QuantumEntangledAndy commented 1 year ago

When you have the time another test would be appreciated. It is working for me now in docker on vlc so hopefully for you too

Veuchez commented 1 year ago

Both in VLC on Windows and in frigate I see the streaming all jerky...

QuantumEntangledAndy commented 1 year ago

I'm not seeing this on my end. But perhaps it's to do with vlc settings.

What are your settings for jitter buffer, clock synchronisation and network cache on vlc?

Veuchez commented 1 year ago

I have the default settings

QuantumEntangledAndy commented 1 year ago

I see. I cannot replicate this. Are you getting lots of messages about jumping to live in the debug logs? Perhaps you could post them.

The only time I get any issues any more is when the stream from the camera is not solid enough. But this is a seperate issue about connectivity not related to VLC buffer part of the code.

Veuchez commented 1 year ago

With previous versions the video streaming was almost perfect. With this version instead of watching a movie I seem to see a gif ... If I had connectivity problems it would also be bad on the Reolink app, instead you can see them perfectly. What command should I use to see the log on windows?

QuantumEntangledAndy commented 1 year ago

Set the environmental variable RUST_LOG=debug

I'm not saying general connectivity issues. But issues perhaps in the other part of the neolink code base. Things like not pulling frames off of the network quickly enough or errors in decoding the frames. There's a lot of moving parts to get things working.

It would be helpful for testing this vlc stuff to do so on the subStream over tcp so we can eliminate that as a source of issue.

Once I can get the vlc working when the packets are coming in well I can look into improving things where the packets are coming in.

I know for example that sometimes the camera drops us when using udp (still haven't figured out why) and after such an event we have to do a reconnect and that causes issues with the playback.

Veuchez commented 1 year ago

Here is the log, if you need longer tell me. LOG.TXT

Checksum commented 1 year ago

I see some really weird playback issue as well. VLC starts out with a blank video for a couple of seconds (probably buffering), and then shows the live stream. But the stream is caught in a loop. The timestamp in the video shows that its just stuck at the same second and keeps looping.

neolink.log

VLC Debug Log (3.0.18 Vetinari).txt

QuantumEntangledAndy commented 1 year ago

A loop happens when frames are not comming in from the camera any more.

Let me try to explain

camera sends frames
we get say 5s of data then the camera stops sending frames
we store 2s in our buffer This means we have frame data From 3-5s
vlc starts playing we mark its start time as 4s
vlc plays for 1s
then vlc wants frames from 5-6s which we don't have Instead the start time is reset and we play frames from 4-5 again

I'll have a run though my code again and see if there's a cleaner way to do this but vlc seems quite picky in how it wants its streams.

If I stop sending frames vlc will drop us

If i send the last frame again vlc will say frame too late and still drop us

QuantumEntangledAndy commented 1 year ago

Ok so removed the jump to live bit of the code. This means reduced error recovery capabilities. We now just leave it to VLC to drop us if it wants. While ffmpeg will just wait forever.

Also swapped to a non-blocking gstreamer queue, this might have been why we stopped getting new frames if we blocked the threads the code wouldn't be able to pull frames from the camera anymore

QuantumEntangledAndy commented 1 year ago

Took a bit more work to get this one ready.

Changes

No jump to live, just leave it on the client
Use non-blocking gstreamer queues
Close all clients when buffers are prepared
Also prepare buffers once
Use multi-threaded tokio runtim
Various changes to speed up github actions
Added some tokio task debugging code

If anyone has time to test please do

I am currently running VLC for 5mins now with neolink in docker with no issues. Will keep running and see

Veuchez commented 1 year ago

I don't know if I'm testing the right version, I downloaded it from here. https://github.com/QuantumEntangledAndy/neolink/suites/12643658589/artifacts/677373974

I keep seeing everything jerky in both mainstream and substream. In VLC it looks better, on FRIGATE it goes badly.

There are many freezes and video artifacts. What program can I use on Windows to save you a clear log?

Checksum commented 1 year ago

No luck yet unfortunately. VLC doesn't seem to be picking up the stream at all. Also, if I stop and play again, VLC can't connect to the server. Also tried with Scrypted which uses ffmpeg, and same behaviour there as well.

neolink.log

QuantumEntangledAndy commented 1 year ago

@Veuchez Last set of builds is here https://github.com/QuantumEntangledAndy/neolink/actions/runs/4871273443

@Checksum that error seems to suggest not even being able to connect to the rtsp server at all. That usually happens if there is something up with your config. If your on docker please ensure you are forwarding 8554 and that you have the bind address in the config as 0.0.0.0

Edit: actually looking closer at your neolink log rather than the vlc it seems to suggest it did connect but that the DTs was always zero which implies that it only sent pre buffer and no frames after the start time.

QuantumEntangledAndy / neolink

Implement fake seek for VLC #68