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

[Thomas Gelf]

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 at 80.2.3.5
T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID at 80.2.3.5
13:49:50 OpenSIPS[762]: Callee was aliased, PSTN - M=INVITE
RURI=sip:my-user at mydomain.tld F=sip:0212345678 at 80.2.3.5
T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID at 80.2.3.5
13:49:50 OpenSIPS[762]: Setting ring timeout to 60 secs - M=INVITE
RURI=sip:my-user at mydomain.tld F=sip:0212345678 at 80.2.3.5
T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID at 80.2.3.5

# 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 at 80.2.3.5
T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID at 80.2.3.5
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 at 80.2.3.5
T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID at 80.2.3.5
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 at 80.2.3.5 (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 at 80.2.3.5
13:49:50 OpenSIPS[771]: Reply - S=180 D=Ringing
F=sip:0212345678 at 80.2.3.5 T=sip:0276543210 at outbound.tld
SRC=111.2.3.5:51076 ID=SOME-CALL-ID at 80.2.3.5
13:49:50 OpenSIPS[757]: Reply - S=180 D=Ringing
F=sip:0212345678 at 80.2.3.5 T=sip:0276543210 at outbound.tld
SRC=111.2.3.4:61000 ID=SOME-CALL-ID at 80.2.3.5

# 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 at 80.2.3.5
T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID at 80.2.3.5
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 at 80.2.3.5
13:50:51 OpenSIPS[758]: Reply - S=487 D=Request Terminated
F=sip:0212345678 at 80.2.3.5 T=sip:0276543210 at outbound.tld
SRC=111.2.3.5:51076 ID=SOME-CALL-ID at 80.2.3.5
13:50:51 OpenSIPS[767]: Reply - S=487 D=Request Cancelled
F=sip:0212345678 at 80.2.3.5 T=sip:0276543210 at outbound.tld
SRC=111.2.3.4:61000 ID=SOME-CALL-ID at 80.2.3.5

# 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 at outbound.tld
SRC=90.1.2.1:5060 ID=SOME-CALL-ID at 80.2.3.5
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 at 80.2.3.5 (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 at 80.2.3.5
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 at 80.2.3.5
T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID at 80.2.3.5
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 at 80.2.3.5
T=sip:0276543210 at outbound.tld SRC=80.2.3.4:5060 ID=SOME-CALL-ID at 80.2.3.5

# 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 at 80.2.3.5 (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 at outbound.tld
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 at 80.2.3.5',
'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