search

tcz / rotary-gpt

I turned my old rotary phone into a ChatGPT-based home assistant and now you can too
MIT License
43 stars 8 forks source link

Audio gets cut off #1

Open sanderversluys opened 1 year ago

sanderversluys commented 1 year ago

Tried to run it myself with my rotary phone and grandstream 801 but audio gets cut off when picking off the phone and also generated audio is downloaded, put on queue but not played.

API keys etc are set just fine.

Any idea based on my log?

debug.log

tcz commented 1 year ago

Hey, first of all, it's awesome that you picked this up!

audio gets cut off

You mean the greeting audio and the audio generated with Polly? Does it play to some extent?

Based on the logs everything looks fine. I leave here my HT801 config for comparison. I think most if them should have the default values, perhaps the jitter buffer size is higher, but I'm not 100% sure because I bought it a long time ago.

Let me know if this helps, if not we can dig deeper.

image image
sanderversluys commented 1 year ago

Thank you for your response.

It seems I got some additional config options but most where similar as yours or the default options. I guess the firmware version may be slightly different.

Screenshot 2023-08-21 at 15 45 25
tcz commented 1 year ago

Both the software and the hardware version actually:

image

Yet it doesn't really explain the issue.

What I'd suggest is to enable the debug on HT801 and look at what's happening there. I made video on how to do that: https://www.loom.com/share/a480ec34037944649282994a1a42cf4a?sid=ce15ddba-bb28-4d7d-abea-d701c5e14cba

tcz commented 1 year ago

Can you test if the latest version works better? See https://github.com/tcz/rotary-gpt/issues/2#issuecomment-1762329789

lundstrom14 commented 1 year ago

Hi @tcz. I have the same problem.

Audio typically gets cut of at "Hello". I have the same issue with new patch with shared sockets unfortunately.

I'll post the HT801 (newer hardware and software versions) logs, maybe you can spot something that's off regarding RTP negotiation?

Super thanks!

tcz commented 1 year ago

Yeah logs might help although they didn't really reveal much for the share socket issue.

lundstrom14 commented 1 year ago

Sometime's I've been able to hear the full greeting message, but very rarely. Could there be something else than RTP negotiation or socket issues?

ht801.log

Application logs. 2023-10-22 17:07:08 MainThread [DEBUG]: Registered function weatherget_weather_today 2023-10-22 17:07:08 MainThread [DEBUG]: Registered function accentchange_accent 2023-10-22 17:07:08 SIP server [INFO]: SIP server started on 0.0.0.0:5060 2023-10-22 17:07:11 SIP server [INFO]: Incoming SIP request b'INVITE' 2023-10-22 17:07:11 SIP server [DEBUG]: b'INVITE sip:192.168.1.98:5060 SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.220.60:5060;branch=z9hG4bK1676250581;rport\r\nFrom: "Mattias" sip:IPCall@192.168.220.60:5060;tag=1370303268\r\nTo: \r\nCall-ID: 1158434412-5060-16@BJC.BGI.CCA.GA\r\nCSeq: 150 INVITE\r\nContact: sip:IPCall@192.168.220.60:5060\r\nMax-Forwards: 70\r\nUser-Agent: Grandstream HT801 1.0.43.11\r\nSupported: replaces, path, timer, eventlist\r\nAllow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE\r\nContent-Type: application/sdp\r\nAccept: application/sdp, application/dtmf-relay\r\nContent-Length: 482\r\n\r\nv=0\r\no=IPCall 8000 8000 IN IP4 192.168.220.60\r\ns=SIP Call\r\nc=IN IP4 192.168.220.60\r\nt=0 0\r\nm=audio 5004 RTP/AVP 0 8 4 18 2 97 123 9 101\r\na=sendrecv\r\na=rtpmap:0 PCMU/8000\r\na=ptime:50\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:4 G723/8000\r\na=rtpmap:18 G729/8000\r\na=fmtp:18 annexb=no\r\na=rtpmap:2 G726-32/8000\r\na=rtpmap:97 iLBC/8000\r\na=fmtp:97 mode=20\r\na=rtpmap:123 opus/48000/2\r\na=fmtp:123 maxplaybackrate=16000\r\na=rtpmap:9 G722/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-16,32-36,54\r\n' 2023-10-22 17:07:11 SIP server [INFO]: SIP response sent 200 2023-10-22 17:07:11 SIP server [DEBUG]: b'SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 192.168.220.60:5060;branch=z9hG4bK1676250581;rport\r\nTo: \r\nFrom: "Mattias" sip:IPCall@192.168.220.60:5060;tag=1370303268\r\nContact: \r\nCall-ID: 1158434412-5060-16@BJC.BGI.CCA.GA\r\nCSeq: 150 INVITE\r\nContent-type: application/sdp\r\nContent-Length: 151\r\n\r\nv=0\no=RotaryGPT 1 1 IN IP4 192.168.1.98\ns=SIP Call\nc=IN IP4 192.168.1.98\r\nt=0 0\r\nm=audio 5004 RTP/AVP 0\r\na=sendrecv\r\na=rtpmap:0 PCMU/8000\r\na=ptime:20\r\n' 2023-10-22 17:07:11 SIP server [DEBUG]: Calling incoming call callbacks with client RTP address 192.168.220.60:5004 2023-10-22 17:07:11 RTP receiver [INFO]: RTP receiver started on 0.0.0.0:5004 2023-10-22 17:07:11 RTP sender [INFO]: RTP sender started with peer 192.168.220.60:5004 2023-10-22 17:07:11 Conversation [INFO]: Conversation started 2023-10-22 17:07:11 Conversation [DEBUG]: Sending greeting 2023-10-22 17:07:11 SIP server [DEBUG]: Finished incoming call callbacks 2023-10-22 17:07:11 SIP server [INFO]: Incoming SIP request b'ACK' 2023-10-22 17:07:11 SIP server [DEBUG]: b'ACK sip:192.168.1.98:5060 SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.220.60:5060;branch=z9hG4bK1083392993;rport\r\nFrom: "Mattias" sip:IPCall@192.168.220.60:5060;tag=1370303268\r\nTo: \r\nCall-ID: 1158434412-5060-16@BJC.BGI.CCA.GA\r\nCSeq: 150 ACK\r\nContact: \r\nMax-Forwards: 70\r\nSupported: replaces, path, timer, eventlist\r\nUser-Agent: Grandstream HT801 1.0.43.11\r\nAllow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE\r\nContent-Length: 0\r\n\r\n' 2023-10-22 17:07:11 RTP sender [DEBUG]: New talkspurt, marker bit set 2023-10-22 17:07:16 Conversation [DEBUG]: Sending greeting 2023-10-22 17:07:17 Conversation [DEBUG]: Starting Whisper request 2023-10-22 17:07:17 RTP sender [DEBUG]: New talkspurt, marker bit set 2023-10-22 17:07:17 Conversation [DEBUG]: Receiving audio 2023-10-22 17:07:19 Conversation [DEBUG]: Silence detected 2023-10-22 17:07:19 Conversation [DEBUG]: Sending Whisper request 2023-10-22 17:07:19 Conversation [DEBUG]: Whisper returned 2023-10-22 17:07:19 Conversation [INFO]: User message: Hello, what is your name? 2023-10-22 17:07:19 Conversation [DEBUG]: Sending GPT request 2023-10-22 17:07:21 Conversation [INFO]: Agent message: My name is Phone Agent. How can I assist you today? 2023-10-22 17:07:21 Conversation [DEBUG]: Sending Polly request b'HTTP/1.1 200 OK\r\nx-amzn-RequestId: d605cec1-6b32-4855-8c8e-8fdfd297bc26\r\nx-amzn-RequestCharacters: 51\r\nContent-Type: audio/pcm\r\nTransfer-Encoding: chunked\r\nDate: Sun, 22 Oct 2023 15:07:20 GMT\r\nConnection: close' 2023-10-22 17:07:21 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:21 RTP sender [DEBUG]: New talkspurt, marker bit set 2023-10-22 17:07:21 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly fully returned, waiting for audio out queue to be consumed 2023-10-22 17:07:25 Conversation [DEBUG]: Audio out queue empty 2023-10-22 17:07:25 Conversation [DEBUG]: Starting Whisper request 2023-10-22 17:07:25 Conversation [DEBUG]: Receiving audio 2023-10-22 17:07:31 Conversation [DEBUG]: Silence detected 2023-10-22 17:07:31 Conversation [DEBUG]: Sending Whisper request 2023-10-22 17:07:31 SIP server [INFO]: Incoming SIP request b'BYE' 2023-10-22 17:07:31 SIP server [DEBUG]: b'BYE sip:192.168.1.98:5060 SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.220.60:5060;branch=z9hG4bK1294677366;rport\r\nFrom: "Mattias" sip:IPCall@192.168.220.60:5060;tag=1370303268\r\nTo: \r\nCall-ID: 1158434412-5060-16@BJC.BGI.CCA.GA\r\nCSeq: 151 BYE\r\nContact: \r\nMax-Forwards: 70\r\nSupported: replaces, path, timer, eventlist\r\nUser-Agent: Grandstream HT801 1.0.43.11\r\nAllow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE\r\nContent-Length: 0\r\n\r\n' 2023-10-22 17:07:31 SIP server [INFO]: SIP response sent 200 2023-10-22 17:07:31 SIP server [DEBUG]: b'SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 192.168.220.60:5060;branch=z9hG4bK1294677366;rport\r\nTo: \r\nFrom: "Mattias" sip:IPCall@192.168.220.60:5060;tag=1370303268\r\nContact: \r\nCall-ID: 1158434412-5060-16@BJC.BGI.CCA.GA\r\nCSeq: 151 BYE\r\nContent-Length: 0\r\n\r\n' 2023-10-22 17:07:31 SIP server [DEBUG]: Calling call ended callbacks 2023-10-22 17:07:31 RTP sender [INFO]: RTP sender stopped Exception in thread RTP receiver: Traceback (most recent call last): File "/usr/lib/python3.7/threading.py", line 917, in _bootstrap_inner self.run() File "/usr/lib/python3.7/threading.py", line 865, in run self._target(*self._args, **self._kwargs) File "/home/pi/git/rotary-gpt/rotarygpt/rtp.py", line 24, in start self._receive_audio() File "/home/pi/git/rotary-gpt/rotarygpt/rtp.py", line 34, in _receive_audio chunk, address = self.shared_socket.recvfrom(160 + 12) # 20ms is 160 8bit samples plus header File "/home/pi/git/rotary-gpt/rotarygpt/rtp.py", line 125, in recvfrom return self.socket.recvfrom(size) OSError: [Errno 9] Bad file descriptor

2023-10-22 17:07:31 Conversation [DEBUG]: Whisper returned 2023-10-22 17:07:31 Conversation [INFO]: Conversation ended 2023-10-22 17:07:31 SIP server [DEBUG]: Finished call ended callbacks

tcz commented 1 year ago

Yup, you can clearly see that exception. Not sure what's causing it, the socket is perhaps closed already for some reason when it's being read.

Unfortunately I can't debug this remotely.

On Sun, 22 Oct 2023 at 17:09, Mattias Lundström @.***> wrote:

Sometime's I've been able to hear the full greeting message, but very rarely. Could there be something else than RTP negotiation or socket issues?

ht801.log https://github.com/tcz/rotary-gpt/files/13063737/ht801.log

2023-10-22 17:07:08 MainThread [DEBUG]: Registered function weatherget_weather_today 2023-10-22 17:07:08 MainThread [DEBUG]: Registered function accentchange_accent 2023-10-22 17:07:08 SIP server [INFO]: SIP server started on 0.0.0.0:5060 2023-10-22 17:07:11 SIP server [INFO]: Incoming SIP request b'INVITE' 2023-10-22 17:07:11 SIP server [DEBUG]: b'INVITE sip:192.168.1.98:5060 SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.220.60:5060;branch=z9hG4bK1676250581;rport\r\nFrom: "Mattias" @.:5060;tag=1370303268\r\nTo: sip: 192.168.1.98:5060\r\nCall-ID: @.\r\nCSeq: 150 INVITE\r\nContact: @.:5060\r\nMax-Forwards: 70\r\nUser-Agent: Grandstream HT801 1.0.43.11\r\nSupported: replaces, path, timer, eventlist\r\nAllow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE\r\nContent-Type: application/sdp\r\nAccept: application/sdp, application/dtmf-relay\r\nContent-Length: 482\r\n\r\nv=0\r\no=IPCall 8000 8000 IN IP4 192.168.220.60\r\ns=SIP Call\r\nc=IN IP4 192.168.220.60\r\nt=0 0\r\nm=audio 5004 RTP/AVP 0 8 4 18 2 97 123 9 101\r\na=sendrecv\r\na=rtpmap:0 PCMU/8000\r\na=ptime:50\r\na=rtpmap:8 PCMA/8000\r\na=rtpmap:4 G723/8000\r\na=rtpmap:18 G729/8000\r\na=fmtp:18 annexb=no\r\na=rtpmap:2 G726-32/8000\r\na=rtpmap:97 iLBC/8000\r\na=fmtp:97 mode=20\r\na=rtpmap:123 opus/48000/2\r\na=fmtp:123 maxplaybackrate=16000\r\na=rtpmap:9 G722/8000\r\na=rtpmap:101 telephone-event/8000\r\na=fmtp:101 0-16,32-36,54\r\n' 2023-10-22 17:07:11 SIP server [INFO]: SIP response sent 200 2023-10-22 17:07:11 SIP server [DEBUG]: b'SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 192.168.220.60:5060;branch=z9hG4bK1676250581;rport\r\nTo: sip: 192.168.1.98:5060\r\nFrom: "Mattias" @.:5060;tag=1370303268\r\nContact: sip:192.168.1.98:5060\r\nCall-ID: @.\r\nCSeq: 150 INVITE\r\nContent-type: application/sdp\r\nContent-Length: 151\r\n\r\nv=0\no=RotaryGPT 1 1 IN IP4 192.168.1.98\ns=SIP Call\nc=IN IP4 192.168.1.98\r\nt=0 0\r\nm=audio 5004 RTP/AVP 0\r\na=sendrecv\r\na=rtpmap:0 PCMU/8000\r\na=ptime:20\r\n' 2023-10-22 17:07:11 SIP server [DEBUG]: Calling incoming call callbacks with client RTP address 192.168.220.60:5004 2023-10-22 17:07:11 RTP receiver [INFO]: RTP receiver started on 0.0.0.0:5004 2023-10-22 17:07:11 RTP sender [INFO]: RTP sender started with peer 192.168.220.60:5004 2023-10-22 17:07:11 Conversation [INFO]: Conversation started 2023-10-22 17:07:11 Conversation [DEBUG]: Sending greeting 2023-10-22 17:07:11 SIP server [DEBUG]: Finished incoming call callbacks 2023-10-22 17:07:11 SIP server [INFO]: Incoming SIP request b'ACK' 2023-10-22 17:07:11 SIP server [DEBUG]: b'ACK sip:192.168.1.98:5060 SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.220.60:5060;branch=z9hG4bK1083392993;rport\r\nFrom: "Mattias" @.:5060;tag=1370303268\r\nTo: sip: 192.168.1.98:5060\r\nCall-ID: @.\r\nCSeq: 150 ACK\r\nContact: sip:192.168.220.60:5060\r\nMax-Forwards: 70\r\nSupported: replaces, path, timer, eventlist\r\nUser-Agent: Grandstream HT801 1.0.43.11\r\nAllow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE\r\nContent-Length: 0\r\n\r\n' 2023-10-22 17:07:11 RTP sender [DEBUG]: New talkspurt, marker bit set 2023-10-22 17:07:16 Conversation [DEBUG]: Sending greeting 2023-10-22 17:07:17 Conversation [DEBUG]: Starting Whisper request 2023-10-22 17:07:17 RTP sender [DEBUG]: New talkspurt, marker bit set 2023-10-22 17:07:17 Conversation [DEBUG]: Receiving audio 2023-10-22 17:07:19 Conversation [DEBUG]: Silence detected 2023-10-22 17:07:19 Conversation [DEBUG]: Sending Whisper request 2023-10-22 17:07:19 Conversation [DEBUG]: Whisper returned 2023-10-22 17:07:19 Conversation [INFO]: User message: Hello, what is your name? 2023-10-22 17:07:19 Conversation [DEBUG]: Sending GPT request 2023-10-22 17:07:21 Conversation [INFO]: Agent message: My name is Phone Agent. How can I assist you today? 2023-10-22 17:07:21 Conversation [DEBUG]: Sending Polly request b'HTTP/1.1 200 OK\r\nx-amzn-RequestId: d605cec1-6b32-4855-8c8e-8fdfd297bc26\r\nx-amzn-RequestCharacters: 51\r\nContent-Type: audio/pcm\r\nTransfer-Encoding: chunked\r\nDate: Sun, 22 Oct 2023 15:07:20 GMT\r\nConnection: close' 2023-10-22 17:07:21 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:21 RTP sender [DEBUG]: New talkspurt, marker bit set 2023-10-22 17:07:21 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-10-22 17:07:22 Conversation [DEBUG]: Polly fully returned, waiting for audio out queue to be consumed 2023-10-22 17:07:25 Conversation [DEBUG]: Audio out queue empty 2023-10-22 17:07:25 Conversation [DEBUG]: Starting Whisper request 2023-10-22 17:07:25 Conversation [DEBUG]: Receiving audio 2023-10-22 17:07:31 Conversation [DEBUG]: Silence detected 2023-10-22 17:07:31 Conversation [DEBUG]: Sending Whisper request 2023-10-22 17:07:31 SIP server [INFO]: Incoming SIP request b'BYE' 2023-10-22 17:07:31 SIP server [DEBUG]: b'BYE sip:192.168.1.98:5060 SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.220.60:5060;branch=z9hG4bK1294677366;rport\r\nFrom: "Mattias" @.:5060;tag=1370303268\r\nTo: sip: 192.168.1.98:5060\r\nCall-ID: @.\r\nCSeq: 151 BYE\r\nContact: sip:192.168.220.60:5060\r\nMax-Forwards: 70\r\nSupported: replaces, path, timer, eventlist\r\nUser-Agent: Grandstream HT801 1.0.43.11\r\nAllow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE\r\nContent-Length: 0\r\n\r\n' 2023-10-22 17:07:31 SIP server [INFO]: SIP response sent 200 2023-10-22 17:07:31 SIP server [DEBUG]: b'SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 192.168.220.60:5060;branch=z9hG4bK1294677366;rport\r\nTo: sip: 192.168.1.98:5060\r\nFrom: "Mattias" @.:5060;tag=1370303268\r\nContact: sip:192.168.1.98:5060\r\nCall-ID: @.\r\nCSeq: 151 BYE\r\nContent-Length: 0\r\n\r\n' 2023-10-22 17:07:31 SIP server [DEBUG]: Calling call ended callbacks 2023-10-22 17:07:31 RTP sender [INFO]: RTP sender stopped Exception in thread RTP receiver: Traceback (most recent call last): File "/usr/lib/python3.7/threading.py", line 917, in _bootstrap_inner self.run() File "/usr/lib/python3.7/threading.py", line 865, in run self._target(self._args, self._kwargs) File "/home/pi/git/rotary-gpt/rotarygpt/rtp.py", line 24, in start self._receive_audio() File "/home/pi/git/rotary-gpt/rotarygpt/rtp.py", line 34, in _receive_audio chunk, address = self.shared_socket.recvfrom(160 + 12) # 20ms is 160 8bit samples plus header File "/home/pi/git/rotary-gpt/rotarygpt/rtp.py", line 125, in recvfrom return self.socket.recvfrom(size) OSError: [Errno 9] Bad file descriptor

2023-10-22 17:07:31 Conversation [DEBUG]: Whisper returned 2023-10-22 17:07:31 Conversation [INFO]: Conversation ended 2023-10-22 17:07:31 SIP server [DEBUG]: Finished call ended callbacks

— Reply to this email directly, view it on GitHub https://github.com/tcz/rotary-gpt/issues/1#issuecomment-1774119366, or unsubscribe https://github.com/notifications/unsubscribe-auth/AABHCCAGPJH7E4BD6BR4CZ3YAUZKBAVCNFSM6AAAAAA3UTJQQCVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTONZUGEYTSMZWGY . You are receiving this because you were mentioned.Message ID: @.***>

lundstrom14 commented 1 year ago

Thanks for your reply.

Posted the HT801 logs above.

Hmm. I don't think the exception above "OSError: [Errno 9] Bad file descriptor" is the issue, at least it was not the exception that I was trying to highlight. Think that part is just race conditions when BYE since there's no mutex on shared socket?