Stream controllable from external

[quantumentangledandy]

Stream controllable from external

[QuantumEntangledAndy]

Is the automatic pause on latest not working for you? I thought I'd gotten that all sorted out now?

Also yes it would be nice to control it externally. I have some ideas to do that over the mqtt interface but I'd like to work getting current features working well before I do the refractor required to control the rtsp from the mqtt.

[sir-andreas]

Thanks for the quick answer. If I enable automatic pause I cannot start streaming (VLC) in a stable way.

When I enable pause and try to start a stream I got this: (tried to start here twice)

[2023-04-16T11:59:40Z INFO neolink::rtsp::states::streaming] Cam1: Starting video stream Sub Stream (Fluent)
[2023-04-16T11:59:40Z INFO neolink::rtsp] Await Client Pause
[2023-04-16T11:59:55Z INFO neolink::rtsp] Motion Pause
[2023-04-16T11:59:55Z INFO neolink::rtsp] Client Resume
[2023-04-16T11:59:55Z INFO neolink::rtsp::states::streaming] Cam1: Starting video stream Sub Stream (Fluent)
[2023-04-16T11:59:55Z INFO neolink::rtsp] Await Client Pause
[2023-04-16T12:00:11Z INFO neolink::rtsp] Join Pause
[2023-04-16T12:00:11Z WARN neolink::rtsp] Cam1: Retryable error: Cam1: Error while streaming

Caused by:
    deadline has elapsed

[2023-04-16T12:00:11Z INFO neolink_core::bc_protocol] Cam1: Local discovery success XXXXXXXXXXXXXX at 192.168.178.92:43694
[2023-04-16T12:00:12Z INFO neolink::rtsp::states::loggedin] Cam1: Camera time is already set: 2023-04-16 14:00:14 +1
[2023-04-16T12:00:13Z INFO neolink::rtsp::states::loggedin] Cam1: Camera reports firmware version v3.0.0.1342_22092001
[2023-04-16T12:00:13Z INFO neolink::rtsp::states::streaming] Cam1: Starting video stream Sub Stream (Fluent)
[2023-04-16T12:00:13Z INFO neolink::rtsp] Pause buffer prepared
[2023-04-16T12:00:13Z INFO neolink::rtsp] Await Client Pause
[2023-04-16T12:00:13Z INFO neolink::rtsp] Client Pause
[2023-04-16T12:00:40Z INFO neolink::rtsp] Client Resume
[2023-04-16T12:00:40Z INFO neolink::rtsp::states::streaming] Cam1: Starting video stream Sub Stream (Fluent)
[2023-04-16T12:00:40Z INFO neolink::rtsp] Await Client Pause
[2023-04-16T12:00:56Z INFO neolink::rtsp] Motion Pause
[2023-04-16T12:00:56Z INFO neolink::rtsp] Client Resume
[2023-04-16T12:00:56Z INFO neolink::rtsp::states::streaming] Cam1: Starting video stream Sub Stream (Fluent)
[2023-04-16T12:00:56Z INFO neolink::rtsp] Await Client Pause
[2023-04-16T12:01:11Z INFO neolink::rtsp] Join Pause
[2023-04-16T12:01:11Z WARN neolink::rtsp] Cam1: Retryable error: Cam1: Error while streaming

Caused by:
    deadline has elapsed

[2023-04-16T12:01:11Z INFO neolink_core::bc_protocol] Cam1: Local discovery success XXXXXXXXXXXXXX at 192.168.178.92:43694
[2023-04-16T12:01:13Z INFO neolink::rtsp::states::loggedin] Cam1: Camera time is already set: 2023-04-16 14:01:14 +1
[2023-04-16T12:01:13Z INFO neolink::rtsp::states::loggedin] Cam1: Camera reports firmware version v3.0.0.1342_22092001
[2023-04-16T12:01:13Z INFO neolink::rtsp::states::streaming] Cam1: Starting video stream Sub Stream (Fluent)
[2023-04-16T12:01:13Z INFO neolink::rtsp] Pause buffer prepared
[2023-04-16T12:01:13Z INFO neolink::rtsp] Await Client Pause
[2023-04-16T12:01:13Z INFO neolink::rtsp] Client Pause

[QuantumEntangledAndy]

deadline has elapsed from streaming means the camera did not send us a video or audio frame for 15seconds. If there is an error in the stream or the camera drops us we get another error. So something odd seems to be going on with your camera that I am not experiencing on my end.

The only time I have observed this is with super HD settings, that my network can't handle and that it takes too long to assemble the frame from the multiple packets required to trasmit something that large

[QuantumEntangledAndy]

Could you enable trace level logging and try again.

export RUST_LOG=trace
neolink rtsp --config=neolink.toml

and post the log here?

[QuantumEntangledAndy]

Ah we can also get deadline has elapsed if the threads are blocked for some reason. Would be nice to have the trace to see if anything has stopped. There's also a general open issue with VLC #68

[sir-andreas]

RUST_LOG=trace

I tried to do this, but the log file created was really HUGE. (50 MB text file in a just 1 min run)
Is there any way to filter that somehow?

Most things I am getting is this:

log

>[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.RecievedPacker: NewData: 1689
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Normal
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Flushing
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Flushing
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Normal
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UDPSource.RecievedPacket: QueueingAck
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Normal
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.RecievedPacket: Ack: UdpAck { connection_id: -182758074, group_id: 0, packet_id: 10, payload: [] }
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Normal
[2023-04-21T07:41:43Z TRACE neolink_core::bc_protocol::connection::udpsource] UDPSource.RecievedPacket: QueueingAck

Any way to reduce the log level?

[QuantumEntangledAndy]

The queuing ack is kinda the thing I'm interested in although I only need it around the end at the point where you get the error about deadline elapsed. I want to see if the underlying stream is still receiving and acknowledging the camera data.

Maybe just send the 20-30 lines around the deadline elapsed

[sir-andreas]

looks not very promising for me:

[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Flushing
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Flushing
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Normal
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UDPSource.RecievedPacket: QueueingAck
[2023-04-21T11:40:38Z INFO neolink::rtsp] Join Pause
[2023-04-21T11:40:38Z WARN neolink::rtsp] Garage: Retryable error: Garage: Error while streaming

Caused by:
deadline has elapsed
[2023-04-21T11:40:38Z TRACE neolink::utils] Camera Info: BcCameraOpt { name: "Garage", channel_id: 0, addrs: [], uid: Some("xxxxxxxxxxxxxxxxx"), port: None, protocol: TcpUdp, discovery: Relay, aux_printing: None, credentials: {"username": "admin", "password": "******"} }
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol] Garage: Starting Local discovery
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol] Starting Relay
[2023-04-21T11:40:38Z TRACE mio::poll] registering event source with poller: token=Token(16777220), interests=READABLE | WRITABLE
[2023-04-21T11:40:38Z TRACE mio::poll] registering event source with poller: token=Token(16777222), interests=READABLE | WRITABLE
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::discovery] client_id: -826755291
[2023-04-21T11:40:38Z DEBUG neolink_core::bc_protocol::connection::discovery] Broadcasting to: [(255.255.255.255, 2015), (255.255.255.255, 2018), (192.168.178.255, 2015), (192.168.178.255, 2018), (172.29.255.255, 2015), (172.29.255.255, 2018), (192.168.79.255, 2015), (192.168.79.255, 2018), (172.23.255.255, 2015), (172.23.255.255, 2018), (172.28.255.255, 2015), (172.28.255.255, 2018), (192.168.255.255, 2015), (192.168.255.255, 2018), (192.168.15.255, 2015), (192.168.15.255, 2018), (172.19.255.255, 2015), (172.19.255.255, 2018), (172.22.255.255, 2015), (172.22.255.255, 2018), (172.18.255.255, 2015), (172.18.255.255, 2018), (172.20.255.255, 2015), (172.20.255.255, 2018), (172.25.255.255, 2015), (172.25.255.255, 2018), (192.168.47.255, 2015), (192.168.47.255, 2018), (192.168.111.255, 2015), (192.168.111.255, 2018), (172.17.255.255, 2015), (172.17.255.255, 2018), (172.21.255.255, 2015), (172.21.255.255, 2018), (192.168.127.255, 2015), (192.168.127.255, 2018), (172.27.255.255, 2015), (172.27.255.255, 2018)]
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::discovery] Also sending to []
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol] Starting Map
[2023-04-21T11:40:38Z TRACE mio::poll] registering event source with poller: token=Token(16777217), interests=READABLE | WRITABLE
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::discovery] client_id: -1256942061
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol] Starting Remote discovery
[2023-04-21T11:40:38Z TRACE mio::poll] registering event source with poller: token=Token(16777221), interests=READABLE | WRITABLE
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Flushing
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Flushing
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Flushing
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Flushing
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Normal
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UDPSource.RecievedPacket: QueueingAck
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.RecievedPacket: Ack: UdpAck { connection_id: 724761965, group_id: 0, packet_id: 64, payload: [] }
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.State: Normal
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UDPSource.RecievedPacket: QueueingAck
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.RecievedPacket: Ack: UdpAck { connection_id: -1597751832, group_id: 0, packet_id: 78, payload: [] }
[2023-04-21T11:40:38Z TRACE neolink_core::bc_protocol::connection::udpsource] UdpPayloadSource.poll_next

[QuantumEntangledAndy]

So this part of the loop is still working. We are still trying to recieve the packets and we are still sending out new acknowledgment packets. We need to look else where.

Let's try some questions to narrow things down. This happens with and without pause or just with pause? If only with pause is it with motion and/or client (please try all combinations)

[sir-andreas]

sorry for the late answer. You are right: It seems that it occurs independently from the pause setting.

What I also recognized is this warning message:

neolink | [2023-04-28T10:31:03Z WARN neolink::rtsp] Garage: Retryable error: Garage: Error while streaming
neolink |
neolink | Caused by:
neolink | deadline has elapsed
neolink | [2023-04-28T10:31:03Z INFO neolink_core::bc_protocol] Garage: Remote discovery success ...
neolink | [2023-04-28T10:31:03Z INFO neolink_core::bc_protocol] Garage: Relay success ...
neolink | [2023-04-28T10:31:03Z INFO neolink_core::bc_protocol] Garage: Local discovery success ...
neolink | [2023-04-28T10:31:05Z WARN neolink_core::bc_protocol::connection::bcconn] Reaching limit of channel
neolink | [2023-04-28T10:31:05Z WARN neolink_core::bc_protocol::connection::bcconn] Remaining: 0 of 100 message space for 4 (ID: 3)

After this error ocured I have to restart the docker container in order to get a valid stream again. Problem also happens with fluent and clear stream

[QuantumEntangledAndy]

I thought I had already fixed this error. It happens when the gatreamer thread or the conversion from bytes to media packets locks up such that the queue fills up (100 packets in the queue).

Do you have any message about error in the stream? Also please confirm you are on the latest build.

[sir-andreas]

I was intentionally on one version before the last one in order not to disturb my analysis. After the uptdate to quantumentangledandy/neolink:latest this WARN does not appear any longer.

But now I still have the issue that the stream is only stable if I disable the pause options. If pause settings are on the stream is behaving like neolink does not discover the open RSTP stream correctly. So it always stops the stream after a few seconds. In this breaks neolink in the background activates the pause of the stream and then restarts it. This repeats as long as I keep the stream player open or the player disconnects because of stream ending.

Without pause settings active everything works like a charm. If just there would not be the battery drain.

Which brings me to my inital question whether there is a possiblility to start and stop the stream by an external function call? Or MqTT command?

[QuantumEntangledAndy]

As I said there is no such command. It's on the todo list. But will require a major refractor. Rtsp is a heavy bit of the code and so is mqtt. They were written to not overlap and have separation of concerns. Id need to do something to sort of wrap up all of the rtsp code into something that mqtt can reliably start and stop while also handeling the errors and keeping it alive. Which will be a lot of work.

I also like to fix current issues before I move on to new features. Which is why I was asking about the pause. Since it's not working. I'm going to revisit it again after my vlc improvement work.

[QuantumEntangledAndy]

Streams should now be start/stoppable from mqtt when using the new mqtt-rtsp command. So closing this, please let me know if you have any issues with it