Open Sternbach-Software opened 11 months ago
Do you have logs and versions of your VoIP adapter? Maybe related? https://github.com/tcz/rotary-gpt/issues/1
Please check the steps suggested there and do the debugging of the device, perhaps something will come up. I'm here to help but I need a bit more info.
Log included below. I'm using the same Grandstream device as #2 . Please help me understand the code here. Once the chunk is sent to audio_chunk_queue_out
, where in the code is the chunk received/sent to RTP? It seems like you are using this Queue as an asynchronous channel of messages which is being collected elsewhere, but I just can't find where. Same goes for the Polly response.
Log (I added some log statements):
2023-09-19 14:46:14 MainThread [DEBUG]: Registered function accent__change_accent 2023-09-19 14:46:14 MainThread [DEBUG]: Registered function weather__get_weather_today 2023-09-19 14:46:14 SIP server [INFO]: SIP server started on 0.0.0.0:5060 2023-09-19 14:46:25 SIP server [DEBUG]: Creating SIP request from address: ('192.168.4.134', 5060) 2023-09-19 14:46:25 SIP server [INFO]: Incoming SIP request b'INVITE' 2023-09-19 14:46:25 SIP server [DEBUG]: b'INVITE sip:192.168.4.160:5060 SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.4.134:5060;branch=z9hG4bK1513924939;rport\r\nFrom: <sip:IPCall@192.168.4.134:5060>;tag=1571951054\r\nTo: <sip:192.168.4.160:5060>\r\nCall-ID: 170190874-5060-7@BJC.BGI.E.BDE\r\nCSeq: 60 INVITE\r\nContact: <sip:IPCall@192.168.4.134:5060>\r\nMax-Forwards: 70\r\nUser-Agent: Grandstream HT801 1.0.49.2\r\nSupported: replaces, path, timer, outbound, 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: 480\r\n\r\nv=0\r\no=IPCall 8000 8000 IN IP4 192.168.4.134\r\ns=SIP Call\r\nc=IN IP4 192.168.4.134\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-09-19 14:46:25 SIP server [INFO]: Response body before mod: None 2023-09-19 14:46:25 SIP server [INFO]: SIP response sent 200 2023-09-19 14:46:25 SIP server [DEBUG]: b'SIP/2.0 200 OK\r\nVia: SIP/2.0/UDP 192.168.4.134:5060;branch=z9hG4bK1513924939;rport\r\nTo: <sip:192.168.4.160:5060>\r\nFrom: <sip:IPCall@192.168.4.134:5060>;tag=1571951054\r\nContact: <sip:192.168.4.160:5060>\r\nCall-ID: 170190874-5060-7@BJC.BGI.E.BDE\r\nCSeq: 60 INVITE\r\nContent-type: application/sdp\r\nContent-Length: 153\r\n\r\nv=0\no=RotaryGPT 1 1 IN IP4 192.168.4.160\ns=SIP Call\nc=IN IP4 192.168.4.160\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-09-19 14:46:25 SIP server [INFO]: Response body after mod: v=0 o=RotaryGPT 1 1 IN IP4 192.168.4.160 s=SIP Call c=IN IP4 192.168.4.160 t=0 0 m=audio 5004 RTP/AVP 0 a=sendrecv a=rtpmap:0 PCMU/8000 a=ptime:20 2023-09-19 14:46:25 SIP server [INFO]: Port: 5004 2023-09-19 14:46:25 SIP server [DEBUG]: Calling incoming call callbacks with client RTP address 192.168.4.134:5004 2023-09-19 14:46:25 SIP server [INFO]: RTP sender: 192.168.4.134:5004 2023-09-19 14:46:25 RTP sender [INFO]: RTP sender started with peer 192.168.4.134:5004 2023-09-19 14:46:25 Conversation [INFO]: Conversation started 2023-09-19 14:46:25 Conversation [DEBUG]: Sending greeting 2023-09-19 14:46:25 SIP server [DEBUG]: Finished incoming call callbacks 2023-09-19 14:46:25 RTP receiver [INFO]: RTP receiver started on 0.0.0.0:5004 2023-09-19 14:46:25 SIP server [DEBUG]: Creating SIP request from address: ('192.168.4.134', 5060) 2023-09-19 14:46:25 SIP server [INFO]: Incoming SIP request b'ACK' 2023-09-19 14:46:25 SIP server [DEBUG]: b'ACK sip:192.168.4.160:5060 SIP/2.0\r\nVia: SIP/2.0/UDP 192.168.4.134:5060;branch=z9hG4bK91898588;rport\r\nFrom: <sip:IPCall@192.168.4.134:5060>;tag=1571951054\r\nTo: <sip:192.168.4.160:5060>\r\nCall-ID: 170190874-5060-7@BJC.BGI.E.BDE\r\nCSeq: 60 ACK\r\nContact: <sip:192.168.4.134:5060;ob>\r\nMax-Forwards: 70\r\nSupported: replaces, path, timer, outbound, eventlist\r\nUser-Agent: Grandstream HT801 1.0.49.2\r\nAllow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE\r\nContent-Length: 0\r\n\r\n' 2023-09-19 14:46:25 Conversation [DEBUG]: Starting Whisper request 2023-09-19 14:46:25 RTP sender [DEBUG]: New talkspurt, marker bit set 2023-09-19 14:46:26 Conversation [DEBUG]: Receiving audio 2023-09-19 14:46:30 Conversation [DEBUG]: Silence detected 2023-09-19 14:46:30 Conversation [DEBUG]: Sending Whisper request 2023-09-19 14:46:31 Conversation [DEBUG]: Whisper returned 2023-09-19 14:46:31 Conversation [INFO]: User message: ←[31;1mHello, how's the weather today?←[0m 2023-09-19 14:46:31 Conversation [DEBUG]: Sending GPT request 2023-09-19 14:46:33 Conversation [INFO]: Function call: {'role': 'assistant', 'content': None, 'function_call': {'name': 'weather__get_weather_today', 'arguments': '{\n "location": "New York",\n "day": "2023-09-19"\n}'}} 2023-09-19 14:46:34 Wait speaker [INFO]: Waited longer than 4.0s to respond, sending wait a moment 2023-09-19 14:46:34 RTP sender [DEBUG]: New talkspurt, marker bit set 2023-09-19 14:46:34 Conversation [INFO]: Function response: ←[32;1mWeather forecast for 2023-09-19 in New York, US Prediction: Mainly clear, partly cloudy, and overcast Max temperature: 21.5°C Min temperature: 13.8°C Precipitation probability: 100%←[0m 2023-09-19 14:46:34 Conversation [DEBUG]: Sending GPT request 2023-09-19 14:46:37 Conversation [INFO]: Agent message: ←[33;1mThe weather today in New York is mainly clear, partly cloudy, and overcast with a maximum temperature of 21.5°C and a minimum temperature of 13.8°C. There is a 100% chance of precipitation.←[0m 2023-09-19 14:46:37 Conversation [DEBUG]: Sending Polly request b'HTTP/1.1 200 OK\r\nx-amzn-RequestId: ABC123-...\r\nx-amzn-RequestCharacters: 189\r\nContent-Type: audio/pcm\r\nTransfer-Encoding: chunked\r\nDate: Tue, 19 Sep 2023 18:46:38 GMT\r\nConnection: close' 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 RTP sender [DEBUG]: New talkspurt, marker bit set 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:38 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:39 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:39 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:39 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:39 Conversation [DEBUG]: Polly chunk arrived, sending to RTP 2023-09-19 14:46:39 Conversation [DEBUG]: Polly fully returned, waiting for audio out queue to be consumed 2023-09-19 14:46:54 Conversation [DEBUG]: Audio out queue empty 2023-09-19 14:46:58 Conversation [DEBUG]: Starting Whisper request 2023-09-19 14:47:00 Conversation [DEBUG]: Receiving audio
Hello,
Regarding the queues, it's being consumed here: https://github.com/tcz/rotary-gpt/blob/9a0f18c3708ebdb727bbc6e864e3f160f15f93e3/rotarygpt/rtp.py#L84
Have you been able to debug HT801 as suggested in #1? I'd love to see the logs. Unfortunately it seems that my HT801 is an older hardware version and it works just fine. Apparently with Cisco ATAs also works, as per #2. I looked at buying a newer HT801 but I can only find HT802 on Amazon - might be worth it nevertheless, but it's a bit pricier just for debugging.
Can you test if the latest version works better? See https://github.com/tcz/rotary-gpt/issues/2#issuecomment-1762329789
I am logging the contents of audio_chunk_queue_out, and it is empty before the polly request and full after the request, but it is never emptied. This makes me think that it is not being sent to the handset correctly. I am not hearing it being played back. And the welcome message is occasionally cut off.