linphone-developers
[Top][All Lists]
Advanced
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

[Linphone-developers] Linphone iOS & Android call will not start

From: Troy Harshberger
Subject: [Linphone-developers] Linphone iOS & Android call will not start
Date: Tue, 22 Dec 2015 08:02:28 -0700
Linphone iOS and Android both appear to suffer from a problem with sip enabled hardware devices.

When a call is placed to or from these devices the app will not fully establish the call. In the case of calling TO those devices no "180 Ringing" is received and I suspect this to be the likely culprit. I have attached debug output of a call into the sip-device.

Please help!

Setup:

rauland nursecall - Connected to Brekeke SIP server
Linphone - Connected to Brekeke SIP server

Note the MSRtpRecv is working but using high CPU. I can provide further information such as pcap files if necessary.

~~LOG~~
2015-12-21 09:23:13.361 Phone+[17400:572970] I ms_filter_unlink: MSFilePlayer:0x7feae3757f20,0-->MSDtmfGen:0x7feae3757fc0,0
2015-12-21 09:23:13.362 Phone+[17400:572970] I ms_filter_unlink: MSDtmfGen:0x7feae3757fc0,0-->MSResample:0x7feae3758420,0
2015-12-21 09:23:13.362 Phone+[17400:572970] I ms_filter_unlink: MSResample:0x7feae3758420,0-->MSAQWrite:0x7feae3758060,0
2015-12-21 09:23:13.372 Phone+[17400:576318] I Ring MSTicker thread exiting
2015-12-21 09:23:13.373 Phone+[17400:572970] I New LinphoneCall [0x7feae3951800] initialized (LinphoneCore version: 3.8.5-727-g4e3ea86)
2015-12-21 09:23:13.374 Phone+[17400:572970] I Call 0x7feae3951800: moving from state LinphoneCallIdle to LinphoneCallOutgoingInit
2015-12-21 09:23:13.374 Phone+[17400:572970] I Linphone core [0x7feae4036200] notifying [call_state_changed]
2015-12-21 09:23:13.375 Phone+[17400:572970] I      PhoneMainView.m:560 - PhoneMainView: Change current view to InCall
2015-12-21 09:23:13.376 Phone+[17400:572970] I      PhoneMainView.m: 76 - Changing rootViewController: Portrait -> Rotating
2015-12-21 09:23:13.382 Phone+[17400:572970] I Cannot determine multicast role for stream type [audio] on call [0x7feae3951800]
2015-12-21 09:23:13.383 Phone+[17400:572970] I RtpSession bound to [0.0.0.0] ports [7238] [7239]
2015-12-21 09:23:13.383 Phone+[17400:572970] I Setting DSCP to 46 for MSAudio stream.
2015-12-21 09:23:13.384 Phone+[17400:572970] I Equalizer location: mic
2015-12-21 09:23:13.384 Phone+[17400:572970] I cannot set noise gate mode to [0] because no volume send
2015-12-21 09:23:13.384 Phone+[17400:572970] I Cannot determine multicast role for stream type [video] on call [0x7feae3951800]
2015-12-21 09:23:13.385 Phone+[17400:572970] I RtpSession bound to [0.0.0.0] ports [9208] [9209]
2015-12-21 09:23:13.385 Phone+[17400:572970] I Setting DSCP to 0 for MSVideo stream.
2015-12-21 09:23:13.386 Phone+[17400:572970] I Contact has been fixed using proxy
2015-12-21 09:23:13.386 Phone+[17400:572970] I Don't put video stream on local offer for call [0x7feae3951800]
2015-12-21 09:23:13.386 Phone+[17400:572970] I Don't put text stream on local offer for call [0x7feae3951800]
2015-12-21 09:23:13.386 Phone+[17400:572970] I ms_filter_link: MSRtpRecv:0x7feae98bad90,0-->MSAUWrite:0x7feae98bb4b0,0
2015-12-21 09:23:13.386 Phone+[17400:572970] I Configuring audio session for playback/record
2015-12-21 09:23:13.387 Phone+[17400:576839] I Priority used: 47
2015-12-21 09:23:13.387 Phone+[17400:576839] I MSAudio MSTicker priority set to SCHED_RR and value (47)
2015-12-21 09:23:13.387 Phone+[17400:572970] I AudioUnit created with type kAudioUnitSubType_VoiceProcessingIO.
2015-12-21 09:23:13.387 Phone+[17400:572970] I Not applying kAudioSessionProperty_PreferredHardwareSampleRate because HW rate already correct [8000]
2015-12-21 09:23:13.388 Phone+[17400:572970] I [sip:address@hidden] calling [sip:address@hidden] on op [0x7feae9c4bd40]
2015-12-21 09:23:13.388 Phone+[17400:572970] I Skipping top route of initial route-set because same as request-uri.
2015-12-21 09:23:13.388 Phone+[17400:572970] I Changing [client] [INVITE] transaction [0x7feae98b9f80], from state [INIT] to [CALLING]
2015-12-21 09:23:13.388 Phone+[17400:572970] I channel [0x7feae5a0bc00]: message sent to [TCP://192.168.1.44:5060], size: [836] bytes
INVITE sip:address@hidden SIP/2.0
Via: SIP/2.0/TCP 192.168.1.253:60416;branch=z9hG4bK.81RBOe2Kf;rport
From: <sip:address@hidden>;tag=2uwIYa94c
To: sip:address@hidden
CSeq: 20 INVITE
Call-ID: jxe0HgKsKh
Max-Forwards: 70
Supported: outbound
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO, UPDATE
Content-Type: application/sdp
Content-Length: 256
Contact: <sip:address@hidden:60416;transport=tcp>;+sip.instance="<urn:uuid:2705ed3a-999d-4baf-8bd8-cd3688313735>"
User-Agent: Phone+_x86_64_iOS9.2/996ff1d (belle-sip/1.4.1)

v=0
o=1510 2332 791 IN IP4 192.168.1.253
s=Talk
c=IN IP4 192.168.1.253
b=AS:380
t=0 0
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7238 RTP/AVPF 0 101
a=rtpmap:101 telephone-event/8000
a=rtcp-fb:* trr-int 5000
2015-12-21 09:23:13.388 Phone+[17400:572970] I Linphone core [0x7feae4036200] notifying [display_status]
2015-12-21 09:23:13.389 Phone+[17400:572970] I Call 0x7feae3951800: moving from state LinphoneCallOutgoingInit to LinphoneCallOutgoingProgress
2015-12-21 09:23:13.389 Phone+[17400:572970] I Linphone core [0x7feae4036200] notifying [call_state_changed]
2015-12-21 09:23:13.395 Phone+[17400:572970] I Background task belle-sip recv channel started. Unknown remaining time since application is not in background.
2015-12-21 09:23:13.395 Phone+[17400:572970] I channel [0x7feae5a0bc00]: starting recv background task with id=[16].
2015-12-21 09:23:13.396 Phone+[17400:572970] I channel [0x7feae5a0bc00]: received [273] new bytes from [TCP://192.168.1.44:5060]:
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 192.168.1.253:60416;branch=z9hG4bK.81RBOe2Kf;rport=60416
From: <sip:address@hidden>;tag=2uwIYa94c
To: sip:address@hidden
Call-ID: jxe0HgKsKh
CSeq: 20 INVITE
Server: Brekeke SIP Server rev.424 Evaluation
Content-Length: 0

2015-12-21 09:23:13.397 Phone+[17400:572970] I channel [0x7feae5a0bc00] [273] bytes parsed
2015-12-21 09:23:13.397 Phone+[17400:572970] I Found transaction matching response.
2015-12-21 09:23:13.397 Phone+[17400:572970] I Changing [client] [INVITE] transaction [0x7feae98b9f80], from state [CALLING] to [PROCEEDING]
2015-12-21 09:23:13.398 Phone+[17400:572970] I op [0x7feae9c4bd40] : set_or_update_dialog() current=[0x0] new=[0x0]
2015-12-21 09:23:13.398 Phone+[17400:572970] I Op [0x7feae9c4bd40] receiving call response [100], dialog is [0x0] in state [BELLE_SIP_DIALOG_NULL]
2015-12-21 09:23:13.398 Phone+[17400:572970] I channel [0x7feae5a0bc00]: ending recv background task with id=[16].
2015-12-21 09:23:13.858 Phone+[17400:572970] I Background task belle-sip recv channel started. Unknown remaining time since application is not in background.
2015-12-21 09:23:13.859 Phone+[17400:572970] I channel [0x7feae5a0bc00]: starting recv background task with id=[17].
2015-12-21 09:23:13.859 Phone+[17400:572970] I channel [0x7feae5a0bc00]: received [568] new bytes from [TCP://192.168.1.44:5060]:
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.1.253:60416;branch=z9hG4bK.81RBOe2Kf;rport=60416
From: <sip:address@hidden>;tag=2uwIYa94c
To: sip:address@hidden;tag=be48f082ds
Call-ID: jxe0HgKsKh
CSeq: 20 INVITE
Supported: timer
Contact: <sip:address@hidden:5060;transport=tcp>
Session-Expires: 1800;refresher=uas
Content-Type: application/sdp
Content-Length: 190

v=0
o=RGS_out 2890844526 2890844526 IN IP4 192.168.1.44
s=Annunciation
c=IN IP4 192.168.1.44
t=0 0
m=audio 10006 RTP/AVP 101 0
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
2015-12-21 09:23:13.861 Phone+[17400:572970] I channel [0x7feae5a0bc00] [378] bytes parsed
2015-12-21 09:23:13.862 Phone+[17400:572970] I channel [0x7feae5a0bc00] read [190] bytes of body from [192.168.1.44:5060]
2015-12-21 09:23:13.863 Phone+[17400:572970] I Found transaction matching response.
2015-12-21 09:23:13.863 Phone+[17400:572970] I Changing [client] [INVITE] transaction [0x7feae98b9f80], from state [PROCEEDING] to [ACCEPTED]
2015-12-21 09:23:13.864 Phone+[17400:572970] I New client dialog [0x7feae98c7e40] , local tag [2uwIYa94c], remote tag [be48f082ds]
2015-12-21 09:23:13.864 Phone+[17400:572970] I Dialog [0x7feae98c7e40]: now updated by transaction [0x7feae98b9f80].
2015-12-21 09:23:13.864 Phone+[17400:572970] I op [0x7feae9c4bd40] : set_or_update_dialog() current=[0x0] new=[0x7feae98c7e40]
2015-12-21 09:23:13.865 Phone+[17400:572970] I Op [0x7feae9c4bd40] receiving call response [200], dialog is [0x7feae98c7e40] in state [BELLE_SIP_DIALOG_CONFIRMED]
2015-12-21 09:23:13.865 Phone+[17400:572970] I Found payload telephone-event/8000 fmtp=
2015-12-21 09:23:13.866 Phone+[17400:572970] I Found payload PCMU/8000 fmtp=
2015-12-21 09:23:13.866 Phone+[17400:572970] I Doing SDP offer/answer process of type outgoing
2015-12-21 09:23:13.866 Phone+[17400:572970] I Processing for stream 0
2015-12-21 09:23:13.866 Phone+[17400:572970] W No matching stream for 0
2015-12-21 09:23:13.867 Phone+[17400:572970] I Computing branch id z9hG4bK.DW-ZyJBrn for message sent statelessly
2015-12-21 09:23:13.867 Phone+[17400:572970] I channel [0x7feae5a0bc00]: message sent to [TCP://192.168.1.44:5060], size: [286] bytes
ACK sip:address@hidden:5060;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 192.168.1.253:60416;rport;branch=z9hG4bK.DW-ZyJBrn
From: <sip:address@hidden>;tag=2uwIYa94c
To: <sip:address@hidden>;tag=be48f082ds
CSeq: 20 ACK
Call-ID: jxe0HgKsKh
Max-Forwards: 70
Content-Length: 0

2015-12-21 09:23:13.867 Phone+[17400:572970] I Call 0x7feae3951800: moving from state LinphoneCallOutgoingProgress to LinphoneCallConnected
2015-12-21 09:23:13.868 Phone+[17400:572970] I Linphone core [0x7feae4036200] notifying [call_state_changed]
2015-12-21 09:23:13.868 Phone+[17400:572970] I    LinphoneManager.m:2290 - Adding CT call center listener [0x7feae99c8ac0]
2015-12-21 09:23:13.868 Phone+[17400:572970] I      PhoneMainView.m:560 - PhoneMainView: Change current view to InCall
2015-12-21 09:23:13.869 Phone+[17400:572970] I Linphone core [0x7feae4036200] notifying [display_status]
2015-12-21 09:23:13.869 Phone+[17400:572970] E Incompatible SDP answer received, need to abort the call
2015-12-21 09:23:13.870 Phone+[17400:572970] I Dialog [0x7feae98c7e40]: now updated by transaction [0x7feae98caa40].
2015-12-21 09:23:13.870 Phone+[17400:572970] I Changing [client] [BYE] transaction [0x7feae98caa40], from state [INIT] to [TRYING]
2015-12-21 09:23:13.870 Phone+[17400:572970] I channel [0x7feae5a0bc00]: message sent to [TCP://192.168.1.44:5060], size: [346] bytes
BYE sip:address@hidden:5060;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 192.168.1.253:60416;branch=z9hG4bK.JV~Eyb8ba;rport
From: <sip:address@hidden>;tag=2uwIYa94c
To: <sip:address@hidden>;tag=be48f082ds
CSeq: 21 BYE
Call-ID: jxe0HgKsKh
Max-Forwards: 70
User-Agent: Phone+_x86_64_iOS9.2/996ff1d (belle-sip/1.4.1)
Content-Length: 0

2015-12-21 09:23:13.870 Phone+[17400:572970] I ms_filter_unlink: MSRtpRecv:0x7feae98bad90,0-->MSAUWrite:0x7feae98bb4b0,0
2015-12-21 09:23:13.871 Phone+[17400:572970] I ===========================================================
2015-12-21 09:23:13.871 Phone+[17400:572970] I                   FILTER USAGE STATISTICS                  
2015-12-21 09:23:13.871 Phone+[17400:572970] I Name                Count     Time/tick (ms)      CPU Usage
2015-12-21 09:23:13.871 Phone+[17400:572970] I -----------------------------------------------------------
2015-12-21 09:23:13.871 Phone+[17400:572970] I MSRtpRecv           48        0.0239388           99.9999   
2015-12-21 09:23:13.872 Phone+[17400:572970] I MSResample          0         0                   0         
2015-12-21 09:23:13.872 Phone+[17400:572970] I MSAQWrite           0         0                   0         
2015-12-21 09:23:13.872 Phone+[17400:572970] I MSDtmfGen           0         0                   0         
2015-12-21 09:23:13.872 Phone+[17400:572970] I MSFilePlayer        0         0                   0         
2015-12-21 09:23:13.873 Phone+[17400:572970] I MSAUWrite           0         0                   0         
2015-12-21 09:23:13.873 Phone+[17400:572970] I MSAURead            0         0                   0         
2015-12-21 09:23:13.873 Phone+[17400:572970] I MSSpeexEC           0         0                   0         
2015-12-21 09:23:13.873 Phone+[17400:572970] I MSRtpSend           0         0                   0         
2015-12-21 09:23:13.873 Phone+[17400:572970] I ===========================================================
2015-12-21 09:23:13.874 Phone+[17400:572970] I Linphone core [0x7feae4036200] notifying [display_status]
2015-12-21 09:23:13.874 Phone+[17400:572970] I Call 0x7feae3951800: moving from state LinphoneCallConnected to LinphoneCallError
2015-12-21 09:23:13.877 Phone+[17400:576839] I MSAudio MSTicker thread exiting
2015-12-21 09:23:13.878 Phone+[17400:572970] I Linphone core [0x7feae4036200] notifying [call_log_updated]
2015-12-21 09:23:13.878 Phone+[17400:572970] I Resetting the current call
2015-12-21 09:23:13.878 Phone+[17400:572970] I Linphone core [0x7feae4036200] notifying [call_state_changed]
2015-12-21 09:23:13.878 Phone+[17400:572970] I    LinphoneManager.m:2280 - Removing CT call center listener [0x7feae99c8ac0]
2015-12-21 09:23:13.879 Phone+[17400:572970] I configuring resampler output to rate=[8000], nchannels=[1]
2015-12-21 09:23:13.879 Phone+[17400:576846] I Priority used: 47
2015-12-21 09:23:13.879 Phone+[17400:572970] I ms_filter_link: MSFilePlayer:0x7feae99c7150,0-->MSDtmfGen:0x7feae99c71f0,0
2015-12-21 09:23:13.879 Phone+[17400:576846] I Ring MSTicker priority set to SCHED_RR and value (47)
2015-12-21 09:23:13.879 Phone+[17400:572970] I ms_filter_link: MSDtmfGen:0x7feae99c71f0,0-->MSResample:0x7feae99c7650,0
2015-12-21 09:23:13.879 Phone+[17400:572970] I ms_filter_link: MSResample:0x7feae99c7650,0-->MSAQWrite:0x7feae99c7290,0
2015-12-21 09:23:13.880 Phone+[17400:572970] I Initializing speex resampler in mode [voip] 
2015-12-21 09:23:13.880 Phone+[17400:572970] I AQ: Configuring audio session for playback
2015-12-21 09:23:13.885 Phone+[17400:572970] I      PhoneMainView.m:560 - PhoneMainView: Change current view to Dialer
2015-12-21 09:23:13.885 Phone+[17400:572970] I      PhoneMainView.m: 76 - Changing rootViewController: Rotating -> Portrait
2015-12-21 09:23:13.889 Phone+[17400:572970] I channel [0x7feae5a0bc00]: ending recv background task with id=[17].
2015-12-21 09:23:13.889 Phone+[17400:572970] I Garbage collecting unowned object of type belle_sip_hop_t
2015-12-21 09:23:13.889 Phone+[17400:572970] I Garbage collecting unowned object of type belle_sdp_session_description_t
2015-12-21 09:23:14.029 Phone+[17400:572970] I Background task belle-sip recv channel started. Unknown remaining time since application is not in background.
2015-12-21 09:23:14.029 Phone+[17400:572970] I channel [0x7feae5a0bc00]: starting recv background task with id=[18].
2015-12-21 09:23:14.030 Phone+[17400:572970] I channel [0x7feae5a0bc00]: received [254] new bytes from [TCP://192.168.1.44:5060]:
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.1.253:60416;branch=z9hG4bK.JV~Eyb8ba;rport=60416
From: <sip:address@hidden>;tag=2uwIYa94c
To: <sip:address@hidden>;tag=be48f082ds
Call-ID: jxe0HgKsKh
CSeq: 21 BYE
Supported: timer
Content-Length: 0

2015-12-21 09:23:14.031 Phone+[17400:572970] I channel [0x7feae5a0bc00] [254] bytes parsed
2015-12-21 09:23:14.031 Phone+[17400:572970] I Found transaction matching response.
2015-12-21 09:23:14.032 Phone+[17400:572970] I Changing [client] [BYE] transaction [0x7feae98caa40], from state [TRYING] to [COMPLETED]
2015-12-21 09:23:14.032 Phone+[17400:572970] I Dialog [0x7feae98c7e40]: now updated by transaction [0x7feae98caa40].
2015-12-21 09:23:14.032 Phone+[17400:572970] I dialog [0x7feae98c7e40] deleted.
2015-12-21 09:23:14.032 Phone+[17400:572970] I op [0x7feae9c4bd40] : set_or_update_dialog() current=[0x7feae98c7e40] new=[0x7feae98c7e40]
2015-12-21 09:23:14.033 Phone+[17400:572970] I Op [0x7feae9c4bd40] receiving call response [200], dialog is [0x7feae98c7e40] in state [BELLE_SIP_DIALOG_TERMINATED]
2015-12-21 09:23:14.033 Phone+[17400:572970] I Changing [client] [BYE] transaction [0x7feae98caa40], from state [COMPLETED] to [TERMINATED]
2015-12-21 09:23:14.033 Phone+[17400:572970] I Client BYE transaction [0x7feae98caa40] terminated
2015-12-21 09:23:14.033 Phone+[17400:572970] I channel [0x7feae5a0bc00]: ending recv background task with id=[18].
2015-12-21 09:23:14.035 Phone+[17400:572970] I Dialog [0x7feae98c7e40] terminated for op [0x7feae9c4bd40]
2015-12-21 09:23:14.035 Phone+[17400:572970] W call_terminated: already terminated, ignoring.
2015-12-21 09:23:14.056 Phone+[17400:572970] I Call 0x7feae3951800: moving from state LinphoneCallError to LinphoneCallReleased
2015-12-21 09:23:14.056 Phone+[17400:572970] I Linphone core [0x7feae4036200] notifying [call_state_changed]
2015-12-21 09:23:14.057 Phone+[17400:572970] I Call [0x7feae3951800] freed.
2015-12-21 09:23:14.057 Phone+[17400:572970] I op [0x7feae9c4bd40] : set_or_update_dialog() current=[0x7feae98c7e40] new=[0x0]
2015-12-21 09:23:16.372 Phone+[17400:572970] I AudioUnit destroyed

~~END LOG~~

Thank you!
-Troy

reply via email to
[Prev in Thread] Current Thread [Next in Thread]