Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Polly response never sent to handset #3

Open
Sternbach-Software opened this issue Sep 12, 2023 · 4 comments
Open

Polly response never sent to handset #3

Sternbach-Software opened this issue Sep 12, 2023 · 4 comments

Comments

@Sternbach-Software
Copy link

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.
@tcz
Copy link
Owner

tcz commented Sep 12, 2023

Do you have logs and versions of your VoIP adapter?
Maybe related? #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.

@Sternbach-Software
Copy link
Author

Sternbach-Software commented Sep 19, 2023 •
edited
Loading

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:[email protected]:5060>;tag=1571951054\r\nTo: <sip:192.168.4.160:5060>\r\nCall-ID: [email protected]\r\nCSeq: 60 INVITE\r\nContact: <sip:[email protected]: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:[email protected]:5060>;tag=1571951054\r\nContact: <sip:192.168.4.160:5060>\r\nCall-ID: [email protected]\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:[email protected]:5060>;tag=1571951054\r\nTo: <sip:192.168.4.160:5060>\r\nCall-ID: [email protected]\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

@tcz
Copy link
Owner

tcz commented Sep 21, 2023

Hello,

Regarding the queues, it's being consumed here:

rotary-gpt/rotarygpt/rtp.py

Line 84 in 9a0f18c

chunk += self.audio_chunk_queue.get(block=False)

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.

@tcz
Copy link
Owner

tcz commented Oct 14, 2023

Can you test if the latest version works better?
See #2 (comment)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@tcz @Sternbach-Software