Andres wrote:
I see this in your output:
:callee's address filled in: 10.31.168.2:16004 (RTP)
Which means it received audio from that IP.
What I don't see is rtpproxy "prefilling" the addresses (caller and callee) with the SDP data which is used to send audio until we know what the real ip/port is. You should be seeing some info like:
pre-filling caller's address with.... pre-filling callee's address with....
If you don't see that, then are you sure that data is coming in the SDP Invite? Without that info, rtpproxy has no way to relay your rtp before receiving rtp from the other end.
Yes, there is a functional SDP payload in the INVITE, the 183 Session Progress, and the 200 OK messages. That's why I have been unable to figure out why rtpproxy didn't have enough information to go on from the INVITE SDP, but was also waiting for something from the first audio packet from the INVITE system. I mean, if there wasn't a SDP payload, would rtpproxy been contacted SER, which it obviously did do.
Since the SIP messages seemed, I didn't think to include them, but here they are (with some numbers obscured) for the same call that I showed rtpproxy debug for:
The INVITE, as received from the calling party by SER (monitored on the interface by ngrep)
U 2008/12/04 19:42:20.471166 72.66.211.59:5060 -> 10.81.90.1:5060 INVITE sip:6829995231@208.66.49.130 SIP/2.0. Via: SIP/2.0/UDP 72.66.211.59:5060;branch=z9hG4bK230c41c1;rport. From: "TROUBLESHOOTING 1000" sip:4692221700@72.66.211.59;tag=as3257bf0a. To: sip:6829995231@208.66.49.130. Contact: sip:4692221700@72.66.211.59. Call-ID: 565aabb151708c9c46c744d2400a454b@72.66.211.59. CSeq: 102 INVITE. User-Agent: Asterisk PBX. Max-Forwards: 70. Date: Thu, 04 Dec 2008 19:42:22 GMT. Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY. Supported: replaces. Content-Type: application/sdp. Content-Length: 415. . v=0. o=root 58770 58770 IN IP4 72.66.211.59. s=session. c=IN IP4 72.66.211.59. t=0 0. m=audio 19994 RTP/AVP 0 3 8 112 5 10 7 97 111. a=rtpmap:0 PCMU/8000. a=rtpmap:3 GSM/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:112 AAL2-G726-32/8000. a=rtpmap:5 DVI4/8000. a=rtpmap:10 L16/8000. a=rtpmap:7 LPC/8000. a=rtpmap:97 iLBC/8000. a=fmtp:97 mode=30. a=rtpmap:111 G726-32/8000. a=silenceSupp:off - - - -. a=ptime:20. a=sendrecv.
The responses from the called switch (monitored on the interface facing the called switch by ngrep)
U 2008/12/04 19:42:20.478463 10.31.0.2:5060 -> 10.31.90.1:5060 SIP/2.0 100 Trying. Call-ID: 565aabb151708c9c46c744d2400a454b@72.66.211.59. CSeq: 102 INVITE. From: "TROUBLESHOOTING 1000" sip:4692221700@72.66.211.59;tag=as3257bf0a. To: sip:6829995231@208.66.49.130;tag=000a0283+1+4e00002+48ad7f8b. Via: SIP/2.0/UDP 10.31.90.1;branch=z9hG4bKc44e.8eae2e65.0. Via: SIP/2.0/UDP 72.66.211.59:5060;branch=z9hG4bK230c41c1;rport=5060. Server: DC-SIP/2.0. Content-Length: 0. .
# U 2008/12/04 19:42:26.926570 10.31.0.2:5060 -> 10.31.90.1:5060 SIP/2.0 183 Session Progress. Call-ID: 565aabb151708c9c46c744d2400a454b@72.66.211.59. CSeq: 102 INVITE. From: "TROUBLESHOOTING 1000" sip:4692221700@72.66.211.59;tag=as3257bf0a. To: sip:6829995231@208.66.49.130;tag=000a0283+1+4e00002+48ad7f8b. Via: SIP/2.0/UDP 10.31.90.1;branch=z9hG4bKc44e.8eae2e65.0. Via: SIP/2.0/UDP 72.66.211.59:5060;branch=z9hG4bK230c41c1;rport=5060. Server: DC-SIP/2.0. Contact: sip:6829995231@10.31.0.2. Content-Type: application/sdp. Content-Length: 173. . v=0 o=- 3437408546 3437408606 IN IP4 10.31.0.2 s=- c=IN IP4 10.31.168.2 t=0 0 m=audio 16004 RTP/AVP 0 a=sendrecv a=ptime:20 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - -
# U 2008/12/04 19:42:37.176531 10.31.0.2:5060 -> 10.31.90.1:5060 SIP/2.0 200 OK. Call-ID: 565aabb151708c9c46c744d2400a454b@72.66.211.59. CSeq: 102 INVITE. From: "TROUBLESHOOTING 1000" sip:4692221700@72.66.211.59;tag=as3257bf0a. To: sip:6829995231@208.66.49.130;tag=000a0283+1+4e00002+48ad7f8b. Via: SIP/2.0/UDP 10.31.90.1;branch=z9hG4bKc44e.8eae2e65.0. Via: SIP/2.0/UDP 72.66.211.59:5060;branch=z9hG4bK230c41c1;rport=5060. Server: DC-SIP/2.0. Contact: sip:6829995231@10.31.0.2. Content-Type: application/sdp. Content-Length: 173. . v=0 o=- 3437408546 3437408606 IN IP4 10.31.0.2 s=- c=IN IP4 10.31.168.2 t=0 0 m=audio 16004 RTP/AVP 0 a=sendrecv a=ptime:20 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - -
Don't forget that SER is altering the IP addresses prior to rtpproxy seeing them and before they are emitted to the other party, so don't let that throw you. Take my word that all the IP address substitutions are correct and are handling calls fine.
Now it sounds like there is some bit of code that is getting skipped or doesn't work right when you use rtpproxy in the mode with two interfaces like I am. Is anybody else using that mode? Maybe the reason no one else is seeing the audio issue is because they only use one interface and the code path is different.
Based on this area of interest in the code, I added some quick debug to rtpproxy and here are the results for a normal call, where the caller is sending audio as soon as the 183 or 200 arrives and audio flows more or less normally:
received command "UE 0d9e8dfd12c8df171a33919e2a536894@72.66.211.59 72.66.211.59 15804 as5c0532d5;1"^M new session 0d9e8dfd12c8df171a33919e2a536894@72.66.211.59, tag as5c0532d5;1 requested, type strong new session on a port 35000 created, tag as5c0532d5;1 C1 C2 C5 C6 C9 sending reply "35000 10.31.168.18 " received command "L 0d9e8dfd12c8df171a33919e2a536894@72.66.211.59 10.31.0.2 25006 as5c0532d5;1 000a0283+1+4d70 003+5a436147" lookup on ports 35000/35000, session timer restarted C1 C2 C5 C6 C9 sending reply "35000 10.81.168.2 "
Now, as you say the "pre-fill" message didn't come out, so note which log messages were emitted and note that the code flowed around the section that would do the pre-fill ("C3"). Other than adding the rtpp_log_write calls and maybe a brace pair to get it within the same conditional, the code is stock.
...
writeport: rtpp_log_write(RTPP_LOG_INFO, sp->log,"C1"); if (pidx >= 0) { if (ia[0] != NULL && ia[1] != NULL) { rtpp_log_write(RTPP_LOG_INFO, sp->log,"C2"); /* * Unless the address provided by client historically * cannot be trusted and address is different from one * that we recorded update it. */ if (spa->untrusted_addr == 0 && !(spa->addr[pidx] != NULL && SA_LEN(ia[0]) == SA_LEN(spa->addr[pidx]) && memcmp(ia[0], spa->addr[pidx], SA_LEN(ia[0])) == 0)) { rtpp_log_write(RTPP_LOG_INFO, sp->log,"C3"); rtpp_log_write(RTPP_LOG_INFO, spa->log, "pre-filling %s's address " "with %s:%s", (pidx == 0) ? "callee" : "caller", addr, port); if (spa->addr[pidx] != NULL) free(spa->addr[pidx]); spa->addr[pidx] = ia[0]; ia[0] = NULL; } if (spa->rtcp->untrusted_addr == 0 && !(spa->rtcp->addr[pidx] != NULL && SA_LEN(ia[1]) == SA_LEN(spa->rtcp->addr[pidx]) && memcmp(ia[1], spa->rtcp->addr[pidx], SA_LEN(ia[1])) == 0)) { rtpp_log_write(RTPP_LOG_INFO, sp->log,"C4"); if (spa->rtcp->addr[pidx] != NULL) free(spa->rtcp->addr[pidx]); spa->rtcp->addr[pidx] = ia[1]; ia[1] = NULL; } } rtpp_log_write(RTPP_LOG_INFO, sp->log,"C5"); spa->asymmetric[pidx] = spa->rtcp->asymmetric[pidx] = asymmetric; spa->canupdate[pidx] = spa->rtcp->canupdate[pidx] = NOT(asymmetric); if (request != 0 || response != 0) { rtpp_log_write(RTPP_LOG_INFO, sp->log,"C6"); if (requested_nsamples > 0) { rtpp_log_write(RTPP_LOG_INFO, sp->log,"C7"); rtpp_log_write(RTPP_LOG_INFO, spa->log, "RTP packets from %s " "will be resized to %d milliseconds", (pidx == 0) ? "callee" : "caller", requested_nsamples / 8); } else if (spa->resizers[pidx].output_nsamples > 0) { rtpp_log_write(RTPP_LOG_INFO, sp->log,"C8"); rtpp_log_write(RTPP_LOG_INFO, spa->log, "Resizing of RTP " "packets from %s has been disabled", (pidx == 0) ? "callee" : "caller"); } spa->resizers[pidx].output_nsamples = requested_nsamples; } } for (i = 0; i < 2; i++) if (ia[i] != NULL) free(ia[i]); cp = buf; len = 0; if (cookie != NULL) { len = sprintf(cp, "%s ", cookie); cp += len; } if (lia[0] == NULL || ishostnull(lia[0])) len += sprintf(cp, "%d\n", lport); else len += sprintf(cp, "%d %s%s\n", lport, addr2char(lia[0]), (lia[0]->sa_family == AF_INET) ? "" : " 6"); rtpp_log_write(RTPP_LOG_INFO, sp->log,"C9"); doreply: doreply(); return 0; ...
So, something in this "if" didn't allow the pre-fill to occur:
if (spa->untrusted_addr == 0 && !(spa->addr[pidx] != NULL && SA_LEN(ia[0]) == SA_LEN(spa->addr[pidx]) && memcmp(ia[0], spa->addr[pidx], SA_LEN(ia[0])) == 0)) {
I'll add some additional debugging later and see if I can spot which of those conditions is the guilty party or parties.