[Linphone-users] Calls immediately terminated when destination picks up

[Tim Crews]

Hello:

We are running linphone on Windows 7 32-bit.  We are using a sequence of 
linphonecsh commands to initiate a phone call to a Cisco phone, by way 
of a Cisco CallManager server.  For example:

linphonecsh init
linphonecsh dial sip:address@hidden

The phone at extension 6875 rings, as desired.  However, when that phone 
is answered, the call is immediately terminated without any explanation 
that is apparent on the client side.  This also happens with the GUI 
client.  It happens using several different PCs to initiate the call.

If we use linphonec instead, with verbose logging turned on, e.g.

linphonec -l log.txt -s sip:address@hidden -S -d 6

we get exactly the same behavior.  It is not obvious to me from the log 
data (see below) why the call is being terminated.  The only warning 
that is logged has to do with missing video.  This is an audio-only call.

Can you provide any pointers on what we are doing wrong in setting up 
the phone calls?

Thanks in advance for any help you can provide.

Tim Crews

-------------------------------

Here is the log file.  I hope it is not against list etiquette to post a 
300-line log file.  I didn't see any advice against it.

Content-Type: application/sdp
Content-Length: 171

v=0
o=CiscoSystemsSIP-GW-UserAgent 4085 8117 IN IP4 192.168.24.240
s=SIP Call
c=IN IP4 192.168.24.240
t=0 0
m=audio 0 RTP/AVP 18 0 8 4 15 3
c=IN IP4 192.168.24.240

ortp-message-Message received from: 192.168.24.240:5060
ortp-message-Message received from: 192.168.24.240:5060
ortp-message-MESSAGE REC. CALLID:14301
ortp-message-Message received from: 192.168.24.240:5060
ortp-message-cb_rcv2xx (id=1)
ortp-message-eXosip: timer sec:5 usec:100000!
ortp-message-linphone process event get a message 29

ortp-message-Contact address updated to <sip:address@hidden> for this 
dialog
ortp-message-ping reply !
ortp-message-Contact has been fixed using OPTIONS to <sip:address@hidden>
ortp-message-allocating transaction ressource 2 2656
ortp-message-allocating ICT context
Contacting <sip:address@hidden>
linphonec> GSTATE_CALL_OUT_INVITE <sip:address@hidden>
ortp-message-DNS resolution with 10.1.3.1:5060
ortp-message-getaddrinfo returned the following addresses:
ortp-message-10.1.3.1 port 5060
ortp-message-Message sent: (to dest=10.1.3.1:5060)
INVITE sip:address@hidden SIP/2.0
Via: SIP/2.0/UDP 10.1.9.102:5060;rport;branch=z9hG4bK27469
From: <sip:address@hidden>;tag=7487
To: <sip:address@hidden>
Call-ID: 2656
CSeq: 20 INVITE
Contact: <sip:address@hidden>
Content-Type: application/sdp
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, 
SUBSCRIBE, INF
O
Max-Forwards: 70
User-Agent: Linphone/3.3.1 (eXosip2/3.3.0)
Subject: Phone call
Content-Length:   400

v=0
o=0001 123456 654321 IN IP4 10.1.9.102
s=A conversation
c=IN IP4 10.1.9.102
t=0 0
m=audio 7078 RTP/AVP 112 111 110 3 0 8 101
a=rtpmap:112 speex/32000/1
a=fmtp:112 vbr=on
a=rtpmap:111 speex/16000/1
a=fmtp:111 vbr=on
a=rtpmap:110 speex/8000/1
a=fmtp:110 vbr=on
a=rtpmap:3 GSM/8000/1
a=rtpmap:0 PCMU/8000/1
a=rtpmap:8 PCMA/8000/1
a=rtpmap:101 telephone-event/8000/1
a=fmtp:101 0-11

ortp-message-cb_sndinvite (id=2)
ortp-message-eXosip: timer sec:0 usec:100000!
ortp-message-Received message:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.1.9.102:5060;rport;branch=z9hG4bK27469
From: <sip:address@hidden>;tag=7487
To: <sip:address@hidden>;tag=A941D3C-270A
Date: Mon, 21 Jun 2010 18:56:12 GMT
Call-ID: 2656
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 20 INVITE
Allow-Events: telephone-event
Content-Length: 0


ortp-message-Message received from: 192.168.24.240:5060
ortp-message-Message received from: 192.168.24.240:5060
ortp-message-MESSAGE REC. CALLID:2656
ortp-message-Message received from: 192.168.24.240:5060
ortp-message-cb_rcv1xx (id=2)
ortp-message-eXosip: timer sec:5 usec:10000!
ortp-message-Received message:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 10.1.9.102:5060;rport;branch=z9hG4bK27469
From: <sip:address@hidden>;tag=7487
To: <sip:address@hidden>;tag=A941D3C-270A
Date: Mon, 21 Jun 2010 18:56:12 GMT
Call-ID: 2656
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 20 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, 
SUBSCRIBE, NOTIF
Y, INFO, REGISTER
Allow-Events: telephone-event
Contact: <sip:address@hidden:5060>
Content-Length: 0


ortp-message-Message received from: 192.168.24.240:5060
ortp-message-Message received from: 192.168.24.240:5060
ortp-message-MESSAGE REC. CALLID:2656
ortp-message-Message received from: 192.168.24.240:5060
ortp-message-cb_rcv1xx (id=2)
ortp-message-eXosip: timer sec:5 usec:10000!
ortp-message-linphone process event get a message 8

ortp-message-CALL_PROCEEDING
ortp-message-Contact address updated to <sip:address@hidden> for this 
dialog
ortp-message-linphone process event get a message 9

ortp-message-CALL_RINGING
ortp-message-Contact address updated to <sip:address@hidden> for this 
dialog
Remote ringing.
linphonec> ortp-message-Remote ringing...
ortp-warning-Failed to open ./share/sounds/linphone/ringback.wav
GSTATE_UNKNOWN_28
ortp-message-Local interface to reach 87.98.157.38 is 10.1.9.102.
ortp-message-cb_nict_kill_transaction (id=1)
ortp-message-Release a terminated transaction
ortp-message-free transaction ressource 1 14301
ortp-message-free nict ressource
ortp-message-eXosip: Reseting timer to 10s before waking up!
ortp-message-Local interface to reach 87.98.157.38 is 10.1.9.102.
ortp-message-Received message:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.1.9.102:5060;rport;branch=z9hG4bK27469
From: <sip:address@hidden>;tag=7487
To: <sip:address@hidden>;tag=A941D3C-270A
Date: Mon, 21 Jun 2010 18:56:12 GMT
Call-ID: 2656
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 20 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, 
SUBSCRIBE, NOTIF
Y, INFO, REGISTER
Allow-Events: telephone-event
Contact: <sip:address@hidden:5060>
Supported: replaces
Content-Type: application/sdp
Content-Disposition: session;handling=required
Content-Length: 240

v=0
o=CiscoSystemsSIP-GW-UserAgent 2358 5787 IN IP4 192.168.24.240
s=SIP Call
c=IN IP4 192.168.24.240
t=0 0
m=audio 16664 RTP/AVP 3 101
c=IN IP4 192.168.24.240
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

ortp-message-Message received from: 192.168.24.240:5060
ortp-message-Message received from: 192.168.24.240:5060
ortp-message-MESSAGE REC. CALLID:2656
ortp-message-Message received from: 192.168.24.240:5060
ortp-message-cb_rcv2xx (id=2)
ortp-message-cb_nict_kill_transaction (id=2)
ortp-warning-keep alive: 4
ortp-message-eXosip: Reseting timer to 10s before waking up!
ortp-message-linphone process event get a message 10

ortp-message-CALL_ANSWERED

ortp-message-Found payload GSM/8000 fmtp=
ortp-message-Found payload telephone-event/8000 fmtp=0-16
ortp-message-Doing SDP offer/answer process
ortp-message-Processing for stream 0
ortp-message-DNS resolution with 192.168.24.240:5060
ortp-message-getaddrinfo returned the following addresses:
ortp-message-192.168.24.240 port 5060
ortp-message-Message sent: (to dest=192.168.24.240:5060)
ACK sip:address@hidden:5060 SIP/2.0
Via: SIP/2.0/UDP 10.1.9.102:5060;rport;branch=z9hG4bK29386
From: <sip:address@hidden>;tag=7487
To: <sip:address@hidden>;tag=A941D3C-270A
Call-ID: 2656
CSeq: 20 ACK
Contact: <sip:address@hidden>
Max-Forwards: 70
User-Agent: Linphone/3.3.1 (eXosip2/3.3.0)
Content-Length: 0


GSTATE_CALL_OUT_CONNECTED
Connected.
linphonec> ortp-message-Payload's bitrate is -1
ortp-message-ms_filter_link: MSWinSndRead:015EA1B8,0-->MSVolume:015EA7E8,0
ortp-message-ms_filter_link: MSVolume:015EA7E8,0-->MSGsmEnc:015EA758,0
ortp-message-ms_filter_link: MSGsmEnc:015EA758,0-->MSRtpSend:015EA2A8,0
ortp-message-ms_filter_link: MSRtpRecv:015EA4B8,0-->MSGsmDec:015EA7B8,0
ortp-message-ms_filter_link: MSGsmDec:015EA7B8,0-->MSDtmfGen:015EA458,0
ortp-message-ms_filter_link: MSDtmfGen:015EA458,0-->MSEqualizer:015EA8A8,0
ortp-message-ms_filter_link: MSEqualizer:015EA8A8,0-->MSVolume:015EA848,0
ortp-message-Received message:
BYE sip:address@hidden:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.24.240:5060;branch=z9hG4bKC3742213
From: <sip:address@hidden>;tag=A941D3C-270A
To: <sip:address@hidden>;tag=7487
Date: Mon, 21 Jun 2010 18:56:26 GMT
Call-ID: 2656
User-Agent: Cisco-SIPGateway/IOS-12.x
Max-Forwards: 70
Timestamp: 1277146586
CSeq: 101 BYE
Reason: Q.850;cause=172
Content-Length: 0


ortp-message-Message received from: 192.168.24.240:57022
ortp-message-Message received from: 192.168.24.240:57022
ortp-message-MESSAGE REC. CALLID:2656
ortp-message-Message received from: 192.168.24.240:57022
ortp-message-This is a request
ortp-message-allocating transaction ressource 3 2656
ortp-message-allocating NIST context
ortp-message-cb_rcvunkrequest (id=3)
ortp-message-cb_rcv? (id=3)
ortp-message-DNS resolution with 192.168.24.240:5060
ortp-message-getaddrinfo returned the following addresses:
ortp-message-192.168.24.240 port 5060
ortp-message-Message sent: (to dest=192.168.24.240:5060)
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.24.240:5060;branch=z9hG4bKC3742213
From: <sip:address@hidden>;tag=A941D3C-270A
To: <sip:address@hidden>;tag=7487
Call-ID: 2656
CSeq: 101 BYE
User-Agent: Linphone/3.3.1 (eXosip2/3.3.0)
Content-Length: 0


ortp-message-cb_snd123456xx (id=3)
ortp-message-ms_filter_link: MSVolume:015EA848,0-->MSWinSndWrite:015EA218,0
ortp-message-eXosip: Reseting timer to 10s before waking up!
ortp-message-eXosip: Reseting timer to 10s before waking up!
ortp-message-win32 timer resolution set to 2 ms
ortp-message-ms_ticker_set_time_func: ticker updated.
ortp-warning-No valid video stream defined.
ortp-message-linphone process event get a message 18

ortp-message-EXOSIP_CALL_MESSAGE_NEW
ortp-message-linphone process event get a message 25

ortp-message-CALL_CLOSED or CANCELLED

ortp-message-Current call terminated...
ortp-message-ms_ticker_set_time_func: ticker updated.
ortp-message-Shutting down sound device (playing: 0) (input-output: 20) 
(notplay
ed: 0)
ortp-message-oRTP-stats:
   Audio session's RTP statistics :
ortp-message- number of rtp packet sent=0
ortp-message- number of rtp bytes sent=0 bytes
ortp-message- number of rtp packet received=0
ortp-message- number of rtp bytes received=0 bytes
ortp-message- number of incoming rtp bytes successfully delivered to the 
applica
tion=0
ortp-message- number of times the application queried a packet that 
didn't exist
=6
ortp-message- number of rtp packet lost=0
ortp-message- number of rtp packets received too late=0
ortp-message- number of bad formatted rtp packets=0
ortp-message- number of packet discarded because of queue overflow=0
ortp-message-ms_filter_unlink: MSWinSndRead:015EA1B8,0-->MSVolume:015EA7E8,0
ortp-message-ms_filter_unlink: MSVolume:015EA7E8,0-->MSGsmEnc:015EA758,0
ortp-message-ms_filter_unlink: MSGsmEnc:015EA758,0-->MSRtpSend:015EA2A8,0
ortp-message-ms_filter_unlink: MSRtpRecv:015EA4B8,0-->MSGsmDec:015EA7B8,0
ortp-message-ms_filter_unlink: MSGsmDec:015EA7B8,0-->MSDtmfGen:015EA458,0
ortp-message-ms_filter_unlink: MSDtmfGen:015EA458,0-->MSEqualizer:015EA8A8,0
ortp-message-ms_filter_unlink: MSEqualizer:015EA8A8,0-->MSVolume:015EA848,0
ortp-message-ms_filter_unlink: 
MSVolume:015EA848,0-->MSWinSndWrite:015EA218,0
ortp-message-Audio MSTicker thread exiting
Call terminated.
linphonec> GSTATE_CALL_END
GSTATE_CALL_IDLE
ortp-message-Notifying all friends that we are in status 1
ortp-message-Local interface to reach 87.98.157.38 is 10.1.9.102.
ortp-message-Local interface to reach 87.98.157.38 is 10.1.9.102.
ortp-warning-keep alive: 0
ortp-message-eXosip: Reseting timer to 10s before waking up!
ortp-message-Local interface to reach 87.98.157.38 is 10.1.9.102.
ortp-message-Local interface to reach 87.98.157.38 is 10.1.9.102.
ortp-message-Local interface to reach 87.98.157.38 is 10.1.9.102.
ortp-warning-keep alive: 1
ortp-message-eXosip: timer sec:11 usec:10000!
ortp-message-Local interface to reach 87.98.157.38 is 10.1.9.102.
Terminating...
No active call.
GSTATE_POWER_SHUTDOWN
ortp-message-Release a terminated transaction
ortp-message-free transaction ressource 2 2656
ortp-message-free ict ressource
ortp-message-free transaction ressource 3 2656
ortp-message-free nist ressource
GSTATE_POWER_OFF