exec does not kill previous command when reconnecting

slyoldfox commented 2 months ago

My doorbell publishes an RTP UDP stream which disconnects every minute.

When the stream disconnects, the (previous) underlying exec process is not killed before the reconnect occurs.

Basically I am using a TCP socket which provides SDP to ffmpeg:

streams:
  doorbell3:
    - "ffmpeg:tcp://192.168.0.20:50000#video=copy#audio=pcma"

This writes the following SDP to the socket:

v=0
m=audio 5000 RTP/AVP 110
c=IN IP4 127.0.0.1
a=rtpmap:110 speex/8000/1
m=video 5002 RTP/AVP 96
c=IN IP4 127.0.0.1
a=rtpmap:96 H264/90000

I can see the stream working as expected on the streams page. After a while the servers stops sending packets to ports 5000 and 5002 and a reconnect will occur which will lead to a bind failed error.

This reconnects happens here: https://github.com/AlexxIT/go2rtc/blob/master/internal/streams/producer.go#L174

The error is quite logical because it will try to bind() to UDP ports 5000 and 5002 using the following underlying command ffmpeg -hide_banner -i tcp://192.168.0.20:50000 -c:v copy -c:a pcm_alaw -ar:a 8000 -ac:a 1 -user_agent ffmpeg/go2rtc -rtsp_transport tcp -f rtsp rtsp://127.0.0.1:8554/61351096f0e2c54e7b8c0c1725be6ebb.

Locally I hacked around this by doing the following (but I am sure a better solution is at hand), which seems to fix the issue:

    if preciousCmd != nil && preciousCmd.Process != nil {
        preciousCmd.Process.Kill()
        preciousCmd = nil
    }
    cmd := exec.Command(args[0], args[1:]...)
    if log.Debug().Enabled() {
        cmd.Stderr = os.Stderr
    }
    preciousCmd = cmd

This is happens here: https://github.com/AlexxIT/go2rtc/blob/master/internal/exec/exec.go#L71

This is on 1.9.0 on Mac Intel

AlexxIT commented 2 months ago

There's a lot of confusion in your post:

tcp://192.168.0.5:50000 (port and IP)
where SDP came from?
m=audio 5000 (port) m=video 5002 (port)
speex/8000/1 - not supported codec
tcp://192.168.0.20:50000 (port and IP)

slyoldfox commented 2 months ago

tcp://192.168.0.5:50000 and tcp://192.168.0.20:50000 were both the same. It's a simple TCP socket that writes a (fixed) SDP. I succesfully use it with the command ffmpeg -f sdp -i tcp://192.168.0.5:5000 ... and transcode the speex codec there to PCMA. The usage of the SDP is mandatory for ffmpeg because you can't use ffmpeg -f rtp -i videoinput -f rtp -i audioinput form the command line.
This intercom sends RTP packets on port 5000 for the audio and 5002 for video - the codecs and ports are fixed on the intercom side
I understand that speex is not supported, but the #audio=pcma option works as expected so it is not really relevant to the issue

The only issue I'm seeing is that the reconnect from the gortc worker doesn't seem to close in time, which causes the ffmpeg process to still be running when the intercom stops sending packets and the go2rtc reconnects. Since ffmpeg will bind() to the UDP ports 5000 and 5002 taken from the SDP - it will fail because the previous ffmpeg is still bound to these ports.

I was looking if pkg/magic/producer.go could support SDP detection from the TCP socket natively, I suppose it might fit in at some point by checking if the first 4 bytes are "v=0", but that's another story :-)

AlexxIT commented 2 months ago

It didn't get any better.

192.168.0.5 and 192.168.0.20 - different IPs, they're definitely not same
50000 and 5000 - different ports

I still don't understand the whole data flow.

PS. SDP over TCP it's really another story. It doesn't meet any standards.

slyoldfox commented 2 months ago

I am sorry if the flow is confusing, I admit that this bticino intercom is quite exotic in its setup.

192.168.0.20 is the IP address of the intercom and exposes the SDP via a normal socket call on TCP port 50000. 192.168.0.5 is my development computer, where I also have a TCP socket running on port 50000 for debugging, ignore this IP, I have changed the initial comment).

Everything starts out with a receiver calling TCP port 50000 on the intercom IP (192.168.0.20). The intercom will return the SDP above in the reply on the socket. Internally, the intercom will setup a SIP call between itself and the outdoor camera unit, it is not really relevant to you, but the TCP socket on port 50000 triggers the SIP call internally.

Once the SIP call is established internally, it will (re)stream the RTP UDP packets on port 5000 (for audio) and RDP UDP packets on port 5002 (for video) - as provided in the SDP by the TCP socket on port 50000 - towards the receiver.

The receiver binds on UDP ports 5000 and 5002 to receive these packets and process them (ffmpeg does this internally after having parsed the SDP).

So to summarize - hopefully a little more clear:

receiver starts ffmpeg with -f sdp -i tcp://192.168.0.20:50000
intercom is listening on TCP port 50000 and returns the SDP which specifies that audio and video will be sent on UDP ports 5000 and 5002 respectively, the intercom starts sending these packets to the IP address to the receiver. These packets are RTP packets over UDP.
ffmpeg on the receiver parses this SDP and binds to UDP ports 5000 and 5002 to process the RTP packets.

AlexxIT commented 2 months ago

Where does intercom get the IP-address to send UDP? Will this be the same address where the TCP request to port 50000 came from or is this configurable separately?
What software is this 50000 port even made for? Does anything other than ffmpeg know how to receive SDP over TCP?
It doesn't make sense for magic/producer.go to support SDP because go2rtc doesn't manage to open random ports to receive UDP data. Also because of your problem - we can't specify the ports ourselves and they may be busy.

OK. I'll try to reproduce your situation about reconnecting issue.

slyoldfox commented 2 months ago

Thank you! If it's any help, this is the command I use to simulate packets sent from the intercom to the receiver:

ffmpeg -re -f lavfi -i "color=red:size=688x480:rate=15" -f lavfi -i "sine=frequency=1000:b=4" -profile:v baseline -preset ultrafast -g 15 -vcodec libx264 -an -tune zerolatency -f rtp "rtp://GO2RTCIP:5002" -vn -ar 8000 -acodec speex -f rtp -payload_type 110 "rtp://GO2RTCIP:5000"

Replace GO2RTCIP with the IP of your local receiver of course.

You will see that ffmpeg spits out an SDP which matches the SDP that gets returned by the socket server on port 50000.

In theory ffmpeg doesn't care if the SDP is provided from a local file (with -i /local/test.sdp) or over a socket (with -i tcp://IP:50000). In some way it is smart enough to detect that the format is SDP and thus providing -f sdp is not really required on the receiver side.

The following snippet runs the socket server on nodejs to simulate the SDP serving on port 50000.

const net = require("net");
const server = new net.createServer(); 

const sdp = `v=0
m=audio 5000 RTP/AVP 110
c=IN IP4 127.0.0.1
a=rtpmap:110 speex/8000/1
m=video 5002 RTP/AVP 96
c=IN IP4 127.0.0.1
a=rtpmap:96 H264/90000`
server.on("connection", client => {
    client.on('close', () => {
        console.log("Socket DISCONNECTED");
    })

    client.on("data", function (data) {
        console.log("Server received data: " + data);
    });
    console.log("Wrote sdp: " + sdp)
    client.write(sdp)
    client.destroy()

});
server.on("listening", () => {
    console.log(`SDP server listening on ${server.address().address}:${server.address().port}`)
})

server.listen(50000, "0.0.0.0");

AlexxIT commented 1 month ago

I can't confirm your problem. Reconnection works fine. Only one ffmpeg active. I'm testing latest master branch in Windows. Maybe problem with go2rtc v1.9.0 or your Mac or something else.

import socket
import subprocess

sdp = b"""v=0
m=audio 5000 RTP/AVP 110
c=IN IP4 127.0.0.1
a=rtpmap:110 speex/8000/1
m=video 5002 RTP/AVP 96
c=IN IP4 127.0.0.1
a=rtpmap:96 H264/90000
"""
exec = "ffmpeg -re -i bbb.mp4 -an -c:v libx264 -g 50 -profile:v high -level:v 4.1 -preset:v superfast -tune:v zerolatency -f rtp rtp://127.0.0.1:5002 -vn -c:a speex -ar:a 8000 -ac:a 1 -f rtp -payload_type 110 rtp://127.0.0.1:5000"

s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
s.bind(("127.0.0.1", 50000))
s.listen()
while True:
    conn, addr = s.accept()
    conn.send(sdp)
    conn.close()
    subprocess.call(exec.split(" "))

streams:
  issue-1084: ffmpeg:tcp://127.0.0.1:50000#video=copy#audio=pcma

slyoldfox commented 1 month ago

Hi, thank you for taking the time to look at this.

I'm not sure what differs, might indeed be OS related (different timeout levels on the socket level?).

At the moment I worked around the issue by randomizing the two ports (5000 and 5002) which are in the SDP, in this case the client never has to bind to the same port and the issue becomes less relevant.

You can close this for now if you'd like, thanks again!

AlexxIT commented 1 month ago

There is a known issue that FFmpeg won't close. It's old. I can't replicate it either. Maybe this is the same problem. Related to some kind of environment.

AlexxIT commented 1 month ago

I found a place in the code. go2rtc really doesn't kill running exec/rtsp. It hopes that the process will kill itself when the connection is closed. It seems in some situations that I can't replicate - it doesn't do that.

slyoldfox commented 1 month ago

Hi, sorry I didn't get back to this earlier. I might have not mentionned an important aspect of the setup.

The device that is sending the audio and video packets (ports 5000 and 5002) is a doorbell, but it only holds the stream of packets alive for 30 seconds. After this, the intercom shuts off and the packets stop flowing on ports 5000/5002.

I am not entirely sure how go2rtc handles this and to be honest I have no clue what should be happening :-)

At the moment of writing, I am closing the socket when the hangup occurs after 30 seconds from the intercom. I am not sure how the internals would be working in that case, since the ffmpeg process would still be running, but not receiving any packets.

If you test this on the client with ffplay tcp://127.0.0.1:50000, you will see that after 30 seconds we're left with this:

 211.58 A-V:  9.011 fd=   0 aq=    0KB vq=    0KB sq=    0B f=0/0

Basically no packets flowing and the ffplay process runs forever until you kill it.

For your test case I suppose you should kill the exec process after a period of time (say 30 seconds) and do the conn.close() when this happens. I think this should mirror the setup on my side. At that time observe what happens when you try to open a new consumer on the client side.

AlexxIT commented 2 weeks ago

Is problem fixed in the latest version?

slyoldfox commented 2 weeks ago

I just fetched 1.9.4 and tried it with my old implementation (I have since then switched to a custom RTSP implementation on my doorbell), unfortunately still seeing the same issue.

Here is a grab from the HA log

$ tail --follow=name .homeassistant/home-assistant.log|grep webrtc
2024-06-19 20:28:01.714 DEBUG (MainThread) [custom_components.webrtc] New client: {'authSig': 'eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiI1IxNzExfQ.ubFWivK_iaax4AqjkRu1re-2zrd2kGfHz751kb6oZ_E', 'url': 'doorbell'}
2024-06-19 20:28:01.825 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:01.824 DBG [webrtc] new consumer src=doorbell
2024-06-19 20:28:01.826 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:01.825 DBG [exec] run rtsp args=["/home/hass/ffmpeg-linux-x64","-hide_banner","-v","error","-i","tcp://192.168.0.XX:50000","-c:v","copy","-c:a","pcm_alaw","-ar:a","8000","-ac:a","1","-user_agent","ffmpeg/go2rtc","-rtsp_transport","tcp","-f","rtsp","rtsp://127.0.0.1:8554/91c5c93ba18576a9c1df738c748738de"]
2024-06-19 20:28:06.168 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:06.168 DBG [exec] run rtsp launch=4.342726413s
2024-06-19 20:28:06.169 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:06.169 DBG [streams] start producer url=ffmpeg:tcp://192.168.0.XX:50000#video=copy#audio=pcma

DOORBELL HANGS UP ABOUT 30 SECONDS LATER HERE

2024-06-19 20:28:50.525 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:50.525 WRN github.com/AlexxIT/go2rtc/internal/streams/producer.go:170 > error="read tcp 127.0.0.1:8554->127.0.0.1:57832: i/o timeout" url=ffmpeg:tcp://192.168.0.XX:50000#video=copy#audio=pcma
2024-06-19 20:28:50.526 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:50.525 DBG [streams] retry=0 to url=ffmpeg:tcp://192.168.0.XX:50000#video=copy#audio=pcma
2024-06-19 20:28:50.526 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:50.525 DBG [exec] run rtsp args=["/home/hass/ffmpeg-linux-x64","-hide_banner","-v","error","-i","tcp://192.168.0.XX:50000","-c:v","copy","-c:a","pcm_alaw","-ar:a","8000","-ac:a","1","-user_agent","ffmpeg/go2rtc","-rtsp_transport","tcp","-f","rtsp","rtsp://127.0.0.1:8554/91c5c93ba18576a9c1df738c748738de"]
2024-06-19 20:28:52.082 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:52.081 DBG [exec] [udp @ 0x7f9381791940] bind failed: Address in use
2024-06-19 20:28:52.083 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:52.083 DBG [exec] [in#0 @ 0x7f93817b2180] Error opening input: Invalid data found when processing input
2024-06-19 20:28:52.083 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input file tcp://192.168.0.XX:50000.
2024-06-19 20:28:52.084 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input files: Invalid data found when processing input
2024-06-19 20:28:52.084 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:52.084 DBG [streams] producer=exec/rtsp
2024-06-19 20:28:52.085 DEBUG (webrtc) [custom_components.webrtc.utils] [udp @ 0x7f9381791940] bind failed: Address in use
2024-06-19 20:28:52.085 DEBUG (webrtc) [custom_components.webrtc.utils] [in#0 @ 0x7f93817b2180] Error opening input: Invalid data found when processing input
2024-06-19 20:28:52.085 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input file tcp://192.168.0.XX:50000.
2024-06-19 20:28:52.085 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input files: Invalid data found when processing input
2024-06-19 20:28:52.085 DEBUG (webrtc) [custom_components.webrtc.utils]
2024-06-19 20:28:53.085 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:53.084 DBG [streams] retry=1 to url=ffmpeg:tcp://192.168.0.XX:50000#video=copy#audio=pcma
2024-06-19 20:28:53.085 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:53.085 DBG [exec] run rtsp args=["/home/hass/ffmpeg-linux-x64","-hide_banner","-v","error","-i","tcp://192.168.0.XX:50000","-c:v","copy","-c:a","pcm_alaw","-ar:a","8000","-ac:a","1","-user_agent","ffmpeg/go2rtc","-rtsp_transport","tcp","-f","rtsp","rtsp://127.0.0.1:8554/91c5c93ba18576a9c1df738c748738de"]
2024-06-19 20:28:53.158 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:53.158 DBG [exec] [sdp @ 0x7f1a9dfdc840] RTP: PT=6e: bad cseq 47a9 expected=0ec6
2024-06-19 20:28:53.381 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:53.381 DBG [exec] [in#0 @ 0x7f9bb00dc180] Error opening input: Invalid data found when processing input
2024-06-19 20:28:53.382 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input file tcp://192.168.0.XX:50000.
2024-06-19 20:28:53.382 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input files: Invalid data found when processing input
2024-06-19 20:28:53.382 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:53.382 DBG [streams] producer=exec/rtsp
2024-06-19 20:28:53.382 DEBUG (webrtc) [custom_components.webrtc.utils] [in#0 @ 0x7f9bb00dc180] Error opening input: Invalid data found when processing input
2024-06-19 20:28:53.383 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input file tcp://192.168.0.XX:50000.
2024-06-19 20:28:53.383 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input files: Invalid data found when processing input
2024-06-19 20:28:53.383 DEBUG (webrtc) [custom_components.webrtc.utils]
2024-06-19 20:28:54.383 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:54.383 DBG [streams] retry=2 to url=ffmpeg:tcp://192.168.0.XX:50000#video=copy#audio=pcma
2024-06-19 20:28:54.383 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:54.383 DBG [exec] run rtsp args=["/home/hass/ffmpeg-linux-x64","-hide_banner","-v","error","-i","tcp://192.168.0.XX:50000","-c:v","copy","-c:a","pcm_alaw","-ar:a","8000","-ac:a","1","-user_agent","ffmpeg/go2rtc","-rtsp_transport","tcp","-f","rtsp","rtsp://127.0.0.1:8554/91c5c93ba18576a9c1df738c748738de"]
2024-06-19 20:28:54.580 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:54.580 DBG [exec] [in#0 @ 0x7f0448e0e180] Error opening input: Invalid data found when processing input
2024-06-19 20:28:54.580 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input file tcp://192.168.0.XX:50000.
2024-06-19 20:28:54.580 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input files: Invalid data found when processing input
2024-06-19 20:28:54.581 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:54.580 DBG [streams] producer=exec/rtsp
2024-06-19 20:28:54.581 DEBUG (webrtc) [custom_components.webrtc.utils] [in#0 @ 0x7f0448e0e180] Error opening input: Invalid data found when processing input
2024-06-19 20:28:54.581 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input file tcp://192.168.0.XX:50000.
2024-06-19 20:28:54.581 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input files: Invalid data found when processing input
2024-06-19 20:28:54.581 DEBUG (webrtc) [custom_components.webrtc.utils]
2024-06-19 20:28:55.582 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:55.581 DBG [streams] retry=3 to url=ffmpeg:tcp://192.168.0.XX:50000#video=copy#audio=pcma
2024-06-19 20:28:55.583 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:55.582 DBG [exec] run rtsp args=["/home/hass/ffmpeg-linux-x64","-hide_banner","-v","error","-i","tcp://192.168.0.XX:50000","-c:v","copy","-c:a","pcm_alaw","-ar:a","8000","-ac:a","1","-user_agent","ffmpeg/go2rtc","-rtsp_transport","tcp","-f","rtsp","rtsp://127.0.0.1:8554/91c5c93ba18576a9c1df738c748738de"]
2024-06-19 20:28:55.784 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:55.783 DBG [exec] [in#0 @ 0x7f6c93f68180] Error opening input: Invalid data found when processing input
2024-06-19 20:28:55.784 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input file tcp://192.168.0.XX:50000.
2024-06-19 20:28:55.784 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input files: Invalid data found when processing input
2024-06-19 20:28:55.785 DEBUG (webrtc) [custom_components.webrtc.utils] 20:28:55.784 DBG [streams] producer=exec/rtsp
2024-06-19 20:28:55.785 DEBUG (webrtc) [custom_components.webrtc.utils] [in#0 @ 0x7f6c93f68180] Error opening input: Invalid data found when processing input
2024-06-19 20:28:55.785 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input file tcp://192.168.0.XX:50000.
2024-06-19 20:28:55.785 DEBUG (webrtc) [custom_components.webrtc.utils] Error opening input files: Invalid data found when processing input
2024-06-19 20:28:55.785 DEBUG (webrtc) [custom_components.webrtc.utils]

Probably doesn't matter much but I'm using a custom rolled ffmpeg static binary from here: https://github.com/slyoldfox/ffmpeg-for-bticino/ (which is a trimmed down fork of the homebridge-ffmpeg implementation)

I'm alright if you wish to close the issue since I'm completely abandonning the ffmpeg tcp:// SDP setup, but if you wish for me to debug some things for you, let me know where to place some breakpoints or additional print lines for you.

AlexxIT / go2rtc

exec does not kill previous command when reconnecting #1084