As you can see I rewrote all IPs, Call-IDs etc - I did so for obvious reasons, wouldn't disclose too many details to the public. There are two Mediaproxy Relays, OpensSIPS, another SIP Proxy, some Cisco Routers, a B2BUA and two UAC's (only one of them is triggering engage_media_proxy) involved in the shown call example. I could simplify the whole thing, just calling from a SIP phone, leaving away the whole PSTN part - but the result doesn't change.
What do you expect to see in the trace / what part are you interested in? RTP coming from the UACs? RTP at the Mediaproxy-Relays? SDP? Please note that the only difference (triggering the failure) is whether it takes 60- or 61+ seconds 'til the call is being picked up. Both endpoints doing the RTP are on public IPs, no NAT involved - they are just forced to use Mediaproxy. I guess the reason must be some timeout, probably forced by Mediaproxy. Cheers, Thomas Josip Djuricic wrote: > Could you include tcpdump? > > Best regards, > > Josip > > -----Original Message----- > From: [email protected] > [mailto:[email protected]] On Behalf Of Thomas Gelf > Sent: Friday, June 19, 2009 3:04 PM > To: [email protected] > Subject: [OpenSIPS-Users] Mediaproxy - timeout issue if ringing for more > than 60 seconds > > Hi list, > > there must be a hidden timeout between the initial INVITE and the first > provisional response with SDP - it seems to equal 60 seconds. Therefore > you hear nothing if you pick up your call after 60 seconds. I tried to > document a whole call, going to Voicemail after 61 seconds. While doing > my tests I also played around with some undocumented setting, without > success (relay_recover_interval). > > Here the call trace (please note that the same call is fine if VM picks > up the call within 60 seconds): > > # Call from PSTN (0212345678) to local user (0276543210, > # [email protected], vmbox: 12345): > > 13:49:50 OpenSIPS[762]: New dialog from trusted peer - M=INVITE > RURI=sip:[email protected] F=sip:[email protected] > T=sip:[email protected] SRC=80.2.3.4:5060 > [email protected] > 13:49:50 OpenSIPS[762]: Callee was aliased, PSTN - M=INVITE > RURI=sip:[email protected] F=sip:[email protected] > T=sip:[email protected] SRC=80.2.3.4:5060 > [email protected] > 13:49:50 OpenSIPS[762]: Setting ring timeout to 60 secs - M=INVITE > RURI=sip:[email protected] F=sip:[email protected] > T=sip:[email protected] SRC=80.2.3.4:5060 > [email protected] > > # Two branches are forked, however there is only one of them in my logs > # (need to move that xlog()-statement to branch_route): > > 13:49:50 OpenSIPS[762]: Local user online - M=INVITE > RURI=sip:[email protected]:1025;line=iqdxv6hz > F=sip:[email protected] > T=sip:[email protected] SRC=80.2.3.4:5060 > [email protected] > 13:49:50 OpenSIPS[762]: Request leaving server, > D-URI='sip:111.2.3.5:51076' - M=INVITE > RURI=sip:[email protected]:1025;line=iqdxv6hz > F=sip:[email protected] > T=sip:[email protected] SRC=80.2.3.4:5060 > [email protected] > 13:49:50 media-dispatcher[1697]: debug: Issuing "update" command to > relay at 90.1.2.3 > > # On one of the relay hosts the call is prepared: > > 13:49:50 media-relay[690]: debug: Received new SDP offer > 13:49:50 media-relay[690]: > mediaproxy.mediacontrol.StreamListenerProtocol starting on 54436 > 13:49:50 media-relay[690]: > mediaproxy.mediacontrol.StreamListenerProtocol starting on 54437 > 13:49:50 media-relay[690]: > mediaproxy.mediacontrol.StreamListenerProtocol starting on 54438 > 13:49:50 media-relay[690]: > mediaproxy.mediacontrol.StreamListenerProtocol starting on 54439 > 13:49:50 media-relay[690]: debug: Added new stream: (audio) > 100.3.4.5:60846 (RTP: Unknown, RTCP: Unknown) <-> 90.1.2.3:54436 <-> > 90.1.2.3:54438 <-> Unknown (RTP: Unknown, RTCP: Unknown) > 13:49:50 media-relay[690]: debug: created new session > [email protected]: [email protected] > (69D9B578-1DC8) --> > [email protected] > > # Both devices are ringing: > > 13:49:50 OpenSIPS[769]: Reply - S=100 D=Trying F=sip:[email protected] > T=sip:[email protected] SRC=111.2.3.4:61000 > [email protected] > 13:49:50 OpenSIPS[771]: Reply - S=180 D=Ringing > F=sip:[email protected] > T=sip:0276543210-XXmmhdotwGcVpVtQvJkt/[email protected] > SRC=111.2.3.5:51076 i...@\õ8¸o* > 13:49:50 OpenSIPS[757]: Reply - S=180 D=Ringing > F=sip:[email protected] > T=sip:0276543210-XXmmhdotwGcVpVtQvJkt/[email protected] > SRC=111.2.3.4:61000 i...@\õ8¸o* > > # Timeout happens, 60 secs are over, call is redirected to VM Server, > # the two active branches are cancelled > > 13:50:51 OpenSIPS[779]: Request leaving server in transaction - M=INVITE > RURI=sip:[email protected] F=sip:[email protected] > T=sip:[email protected] SRC=80.2.3.4:5060 > [email protected] > 13:50:51 OpenSIPS[776]: Reply - S=100 D=Trying F=sip:[email protected] > T=sip:[email protected] SRC=90.1.2.1:5060 > [email protected] > 13:50:51 OpenSIPS[758]: Reply - S=487 D=Request Terminated > F=sip:[email protected] > T=sip:0276543210-XXmmhdotwGcVpVtQvJkt/[email protected] > SRC=111.2.3.5:51076 i...@\õ8¸o* > 13:50:51 OpenSIPS[767]: Reply - S=487 D=Request Cancelled > F=sip:[email protected] > T=sip:0276543210-XXmmhdotwGcVpVtQvJkt/[email protected] > SRC=111.2.3.4:61000 i...@\õ8¸o* > > # VM Server waits 1 additional second and then picks up the call (early > # media): > > 13:50:52 OpenSIPS[770]: Reply - S=183 D=Session Progress > F=sip:[email protected] > T=sip:0276543210-XXmmhdotwGcVpVtQvJkt/[email protected] > SRC=90.1.2.1:5060 i...@\õ8¸o* > 13:50:52 media-dispatcher[1697]: debug: Issuing "update" command to > relay at 90.1.2.3 > > # The update reaches the relay - no RTP info yet: > > 13:50:52 media-relay[690]: debug: Got traffic information for stream: > (audio) 100.3.4.5:60846 (RTP: Unknown, RTCP: Unknown) <-> 90.1.2.3:54436 > <-> 90.1.2.3:54438 <-> Unknown (RTP: 90.1.2.1:10262, RTCP: Unknown) > 13:50:52 media-relay[690]: debug: updating existing session > [email protected]: [email protected] > (69D9B578-1DC8) --> > [email protected] > 13:50:52 media-relay[690]: debug: Received updated SDP answer > 13:50:52 media-relay[690]: debug: Got initial answer from callee for > stream: (audio) 100.3.4.5:60846 (RTP: Unknown, RTCP: Unknown) <-> > 90.1.2.3:54436 <-> 90.1.2.3:54438 <-> 90.1.2.1:10262 (RTP: > 90.1.2.1:10262, RTCP: Unknown) > > # Traffic starts in one direction, however I'm unable to hear something: > > 13:50:57 media-relay[690]: debug: Got traffic information for stream: > (audio) 100.3.4.5:60846 (RTP: Unknown, RTCP: Unknown) <-> 90.1.2.3:54436 > <-> 90.1.2.3:54438 <-> 90.1.2.1:10262 (RTP: 90.1.2.1:10262, RTCP: > 90.1.2.1:10263) > > # After the announcement the call is accepted, message registration > # starts: > > 13:51:03 OpenSIPS[757]: Reply - S=200 D=OK F=sip:[email protected] > T=sip:[email protected] SRC=90.1.2.1:5060 > [email protected] > 13:51:03 media-dispatcher[1697]: debug: Issuing "update" command to > relay at 90.1.2.3 > 13:51:03 OpenSIPS[776]: Loose routing detected - M=ACK > RURI=sip:[email protected]:5060 F=sip:[email protected] > T=sip:[email protected] SRC=80.2.3.4:5060 > [email protected] > 13:51:03 OpenSIPS[776]: Request leaving server, D-URI='<null>' - M=ACK > RURI=sip:[email protected]:5060 F=sip:[email protected] > T=sip:[email protected] SRC=80.2.3.4:5060 > [email protected] > > # Update reaches the relay - but RTP information for the caller is still > # unknown (please note that SDP is fine, correctly parsed by QOS modul, > # available via MI - and also fine for Mediaproxy if timeout is below 60 > # secs): > > 13:51:03 media-relay[690]: debug: updating existing session > [email protected]: [email protected] > (69D9B578-1DC8) --> > [email protected] > 13:51:03 media-relay[690]: debug: Received updated SDP answer > 13:51:03 media-relay[690]: debug: Unchanged stream: (audio) > 100.3.4.5:60846 (RTP: Unknown, RTCP: Unknown) <-> 90.1.2.3:54436 <-> > 90.1.2.3:54438 <-> 90.1.2.1:10262 (RTP: 90.1.2.1:10262, RTCP: > 90.1.2.1:10263) > > # If I do not hang up and wait (hearing nothing) - after some seconds > # the call has been teared down: > > 13:51:20 media-relay[690]: debug: expired session [email protected]: > [email protected] (69D9B578-1DC8) --> > 0276543210-XXmmhdotwGcVpVtQvJkt/[email protected] > 13:51:20 media-relay[690]: (Port 54436 Closed) > 13:51:20 media-relay[690]: (Port 54437 Closed) > 13:51:20 media-relay[690]: (Port 54438 Closed) > 13:51:20 media-relay[690]: (Port 54439 Closed) > > # Dispatcher receives the timeout and tells OpenSIPS to stop the call: > > 13:51:20 media-dispatcher[1697]: session with call_id > [email protected] from relay 90.1.2.3 did timeout > 13:51:20 media-dispatcher[1697]: debug: Got statistics: {'from_tag': > '69D9B578-1DC8', 'dialog_id': '2475:922919439', 'start_time': > 1245412252.01, 'timed_out': True, 'call_id': '[email protected]', > 'to_tag': 'as4a00af3c', 'streams': [{'status': 'no-traffic timeout', > 'caller_codec': 'Unknown', 'post_dial_delay': 61.350157022499999, > 'callee_codec': 'G711a', 'start_time': 0, 'caller_bytes': 0, > 'callee_bytes': 0, 'caller_packets': 0, 'end_time': 28, 'callee_remote': > '90.1.2.1:10262', 'caller_remote': 'Unknown', 'media_type': 'audio', > 'callee_local': '90.1.2.3:54438', 'timeout_wait': 90, 'caller_local': > '90.1.2.3:54436', 'callee_packets': 0}], 'duration': 28, 'to_uri': > '[email protected]', 'from_uri': > '[email protected]', > 'callee_ua': 'ROL B2BUA', 'caller_ua': 'Cisco-SIPGateway/IOS-12.x'} > 13:51:20 testproxy media-dispatcher[1697]: > mediaproxy.interfaces.opensips.UNIXSocketProtocol starting on > '/var/run/mediaproxy/opensips_01.sock' > > Any idea where to look for this timeout? > > Kind regards, > Thomas Gelf > > > _______________________________________________ > Users mailing list > [email protected] > http://lists.opensips.org/cgi-bin/mailman/listinfo/users _______________________________________________ Users mailing list [email protected] http://lists.opensips.org/cgi-bin/mailman/listinfo/users
