[OpenSIPS-Users] Mediaproxy - timeout issue if ringing for more than 60 seconds

Fri Jun 19 15:58:14 CEST 2009

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: users-bounces at lists.opensips.org
> [mailto:users-bounces at lists.opensips.org] On Behalf Of Thomas Gelf
> Sent: Friday, June 19, 2009 3:04 PM
> To: users at lists.opensips.org
> 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,
> # my-user at mydomain.tld, vmbox: 12345):
> 
> 13:49:50 OpenSIPS[762]: New dialog from trusted peer - M=INVITE
> RURI=sip:0276543210 at my.proxy.tld F=sip:0212345678-oFeypGxiKV4 at public.gmane.org
> T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID-oFeypGxiKV4 at public.gmane.org
> 13:49:50 OpenSIPS[762]: Callee was aliased, PSTN - M=INVITE
> RURI=sip:my-user at mydomain.tld F=sip:0212345678-oFeypGxiKV4 at public.gmane.org
> T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID-oFeypGxiKV4 at public.gmane.org
> 13:49:50 OpenSIPS[762]: Setting ring timeout to 60 secs - M=INVITE
> RURI=sip:my-user at mydomain.tld F=sip:0212345678-oFeypGxiKV4 at public.gmane.org
> T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID-oFeypGxiKV4 at public.gmane.org
> 
> # 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:my-user at 10.0.0.10:1025;line=iqdxv6hz F=sip:0212345678-oFeypGxiKV4 at public.gmane.org
> T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID-oFeypGxiKV4 at public.gmane.org
> 13:49:50 OpenSIPS[762]: Request leaving server,
> D-URI='sip:111.2.3.5:51076' - M=INVITE
> RURI=sip:my-user at 10.0.0.10:1025;line=iqdxv6hz F=sip:0212345678-oFeypGxiKV4 at public.gmane.org
> T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID-oFeypGxiKV4 at public.gmane.org
> 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
> SOME-CALL-ID at 80.2.3.5: 0212345678-oFeypGxiKV4 at public.gmane.org (69D9B578-1DC8) -->
> 0276543210 at outbound.tld
> 
> # Both devices are ringing:
> 
> 13:49:50 OpenSIPS[769]: Reply - S=100 D=Trying F=sip:0212345678 at 80.2.3.5
> T=sip:0276543210 at outbound.tld SRC=111.2.3.4:61000 ID=SOME-CALL-ID-oFeypGxiKV4 at public.gmane.org
> 13:49:50 OpenSIPS[771]: Reply - S=180 D=Ringing
> F=sip:0212345678 at 80.2.3.5 T=sip:0276543210-XXmmhdotwGcVpVtQvJkt/w at public.gmane.org
> SRC=111.2.3.5:51076 ID@‚\õ8¸O*
> 13:49:50 OpenSIPS[757]: Reply - S=180 D=Ringing
> F=sip:0212345678 at 80.2.3.5 T=sip:0276543210-XXmmhdotwGcVpVtQvJkt/w at public.gmane.org
> SRC=111.2.3.4:61000 ID@‚\õ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:12345 at vm.mydomain.tld F=sip:0212345678-oFeypGxiKV4 at public.gmane.org
> T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID-oFeypGxiKV4 at public.gmane.org
> 13:50:51 OpenSIPS[776]: Reply - S=100 D=Trying F=sip:0212345678 at 80.2.3.5
> T=sip:0276543210 at outbound.tld SRC=90.1.2.1:5060 ID=SOME-CALL-ID-oFeypGxiKV4 at public.gmane.org
> 13:50:51 OpenSIPS[758]: Reply - S=487 D=Request Terminated
> F=sip:0212345678 at 80.2.3.5 T=sip:0276543210-XXmmhdotwGcVpVtQvJkt/w at public.gmane.org
> SRC=111.2.3.5:51076 ID@‚\õ8¸O*
> 13:50:51 OpenSIPS[767]: Reply - S=487 D=Request Cancelled
> F=sip:0212345678 at 80.2.3.5 T=sip:0276543210-XXmmhdotwGcVpVtQvJkt/w at public.gmane.org
> SRC=111.2.3.4:61000 ID@‚\õ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:0212345678 at 80.2.3.5 T=sip:0276543210-XXmmhdotwGcVpVtQvJkt/w at public.gmane.org
> SRC=90.1.2.1:5060 ID@‚\õ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
> SOME-CALL-ID at 80.2.3.5: 0212345678-oFeypGxiKV4 at public.gmane.org (69D9B578-1DC8) -->
> 0276543210 at outbound.tld
> 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:0212345678 at 80.2.3.5
> T=sip:0276543210 at outbound.tld SRC=90.1.2.1:5060 ID=SOME-CALL-ID-oFeypGxiKV4 at public.gmane.org
> 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:12345 at 90.1.2.1:5060 F=sip:0212345678-oFeypGxiKV4 at public.gmane.org
> T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID-oFeypGxiKV4 at public.gmane.org
> 13:51:03 OpenSIPS[776]: Request leaving server, D-URI='<null>' - M=ACK
> RURI=sip:12345 at 90.1.2.1:5060 F=sip:0212345678-oFeypGxiKV4 at public.gmane.org
> T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID-oFeypGxiKV4 at public.gmane.org
> 
> # 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
> SOME-CALL-ID at 80.2.3.5: 0212345678-oFeypGxiKV4 at public.gmane.org (69D9B578-1DC8) -->
> 0276543210 at outbound.tld
> 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 SOME-CALL-ID at 80.2.3.5:
> 0212345678 at 80.2.3.5 (69D9B578-1DC8) --> 0276543210-XXmmhdotwGcVpVtQvJkt/w at public.gmane.org
> 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
> SOME-CALL-ID at 80.2.3.5 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': 'SOME-CALL-ID at 80.2.3.5',
> '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':
> '0276543210 at outbound.tld', 'from_uri': '0212345678-oFeypGxiKV4 at public.gmane.org',
> '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
> Users at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users