Hello all,
I was investigating a problem found by someone regarding an warning/error
trace during Xfer scenario.
This situation does actually NOT end into a failing situation
Scenario:
1. (PJSIP) SIP-line (IVR) has a dialog on hold and an active dialog
(ready-state)
2. Application issues an CTI manipulated TransferCall to the SIP-PBX, and
after 200ms (as security backup) it also initiates a transfer on the
IVR-line.
Normally the SIP-PBX has already transferred the call and so the IVR-line
receives a BYE for both dialogs.
3. PJSIP gets 100-TRYING on the REFER followed by 500-Server Error. The
error was due to the fact the SIP-PBX has already started the transfer
internally.
Probably the 500-Server Error is not the most clean solution, but this is
what we get....
4. PJSIP handles the 500 and sets the state TERMINATED, but it thinks it is
actually handling a NOTIFY so it checks for the body (which doesn't exist).
It now expects a body which doesn't exist => warning log and exiting
handling...
See next PJSIP logs below.
With regards,
Eize Slange
#### Sending REFER ####
#######################
StackDll:dll_xferCallWithReplaces(call 34, dst 35)
dlg044F9ECC Module mod-evsub added as dialog usage, data=0459947C
evsub045990E4 UAC subscription created, using dialog dlg044F9ECC
dlg044F9ECC Session count inc to 5 by mod-evsub
endpoint Request msg REFER/cseq=14201 (tdta04542EA8) created.
dlg044F9ECC Sending Request msg REFER/cseq=14201 (tdta04542EA8)
tsx045407F4 Transaction created for Request msg REFER/cseq=14200
(tdta04542EA8)
tsx045407F4 Sending Request msg REFER/cseq=14200 (tdta04542EA8) in
state Null
sip_resolve.c Target '192.168.12.81:0' type=UDP resolved to '
192.168.12.81:5060' type=UDP (UDP transport)
pjsua_core.c TX 848 bytes Request msg REFER/cseq=14200 (tdta04542EA8) to
UDP 192.168.12.81:5060:
REFER sip:4003 at 192.168.12.81;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.12.83:52743
;rport;branch=z9hG4bKPj310d3901d6a3472b807578ec08dcc0d8
Max-Forwards: 70
From: <sip:4916@192.168.12.81>;tag=480aa105e38d42e0bf93e342610a2844
To: "User4003" <sip:4003 at phoenix.local
>;tag=fef42533-fb81-41fc-b3ed06b6dbcc4d0f
Contact: "4916" <sip:4916 at 192.168.12.83:52743>
Call-ID: 4f0ce72c-c6f6-4ef4-b84fe93dc51a3762 at 192.168.12.81
CSeq: 14200 REFER
Event: refer
Expires: 600
Accept: message/sipfrag;version=2.0
Allow-Events: presence, message-summary, refer
Refer-To: <sip:4005 at phoenix.local
?Require=replaces&Replaces=a723354c-f1a9-4071-b2a71eeeec8cd62b at 192.168.12.81Bto-tagD8a595828-fa29-4d21-b370168266fd90fbBfrom-tagD
?
tsx045407F4 State changed from Null to Calling, event=TX_MSG
dlg044F9ECC Transaction tsx045407F4 state changed to Calling
evsub045990E4 Subscription state changed NULL --> SENT
StackDll:_xfer_replaces(call 34); Status Success.
#### RECV 100-TRYING ####
#########################
sip_endpoint.c Processing incoming message: Response msg
100/REFER/cseq=14200 (rdata045DF09C)
pjsua_core.c RX 503 bytes Response msg 100/REFER/cseq=14200
(rdata045DF09C) from UDP 192.168.12.81:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.12.83:52743
;branch=z9hG4bKPj310d3901d6a3472b807578ec08dcc0d8
To: "User4003" <sip:4003 at phoenix.local
>;tag=fef42533-fb81-41fc-b3ed06b6dbcc4d0f
From: <sip:4916@192.168.12.81>;tag=480aa105e38d42e0bf93e342610a2844
Call-ID: 4f0ce72c-c6f6-4ef4-b84fe93dc51a3762 at 192.168.12.81
CSeq: 14200 REFER
Event: refer
Server: Sphericall/8.0.0 Build/561
Allow:
INVITE,ACK,CANCEL,OPTIONS,REFER,BYE,REGISTER,SUBSCRIBE,NOTIFY,UPDATE,PRACK,MESSAGE,INFO
Content-Length: 0
--end msg--
tsx045407F4 Incoming Response msg 100/REFER/cseq=14200 (rdata045DF09C)
in state Calling
tsx045407F4 State changed from Calling to Proceeding, event=RX_MSG
dlg044F9ECC Received Response msg 100/REFER/cseq=14200 (rdata045DF09C)
dlg044F9ECC Transaction tsx045407F4 state changed to Proceeding
#### RECV 500-Server Error ####
###############################
sip_endpoint.c Processing incoming message: Response msg
500/REFER/cseq=14200 (rdata045DF09C)
pjsua_core.c RX 518 bytes Response msg 500/REFER/cseq=14200
(rdata045DF09C) from UDP 192.168.12.81:5060:
SIP/2.0 500 Internal Server Error
Via: SIP/2.0/UDP 192.168.12.83:52743
;branch=z9hG4bKPj310d3901d6a3472b807578ec08dcc0d8
To: "User4003" <sip:4003 at phoenix.local
>;tag=fef42533-fb81-41fc-b3ed06b6dbcc4d0f
From: <sip:4916@192.168.12.81>;tag=480aa105e38d42e0bf93e342610a2844
Call-ID: 4f0ce72c-c6f6-4ef4-b84fe93dc51a3762 at 192.168.12.81
CSeq: 14200 REFER
Event: refer
Server: Sphericall/8.0.0 Build/561
Allow:
INVITE,ACK,CANCEL,OPTIONS,REFER,BYE,REGISTER,SUBSCRIBE,NOTIFY,UPDATE,PRACK,MESSAGE,INFO
Content-Length: 0
--end msg--
tsx045407F4 Incoming Response msg 500/REFER/cseq=14200 (rdata045DF09C)
in state Proceeding
tsx045407F4 State changed from Proceeding to Completed, event=RX_MSG
dlg044F9ECC Received Response msg 500/REFER/cseq=14200 (rdata045DF09C)
dlg044F9ECC Transaction tsx045407F4 state changed to Completed
### HERE PJSIP thinks it is handling a NOTIFY message !!! ###
#############################################################
evsub045990E4 Subscription state changed SENT --> TERMINATED
pjsua_call.c Xfer client subscription terminated
pjsua_call.c Warning: received NOTIFY without message body
### Immediately followed by the BYE's because PBX already transfered parties
###
################################################################################
sip_endpoint.c Processing incoming message: Request msg
BYE/cseq=1314086103 (rdata045DF09C)
pjsua_core.c RX 429 bytes Request msg BYE/cseq=1314086103
(rdata045DF09C) from UDP 192.168.12.81:5060:
BYE sip:4916 at 192.168.12.83:52743 SIP/2.0
Via: SIP/2.0/UDP 192.168.12.81:5060
;branch=z9hG4bK1415618c-b921-4d66-a80393079fcee148
From: <sip:4005@phoenix.local>;tag=8a595828-fa29-4d21-b370168266fd90fb
To: <sip:4916 at 192.168.12.81>;tag=20a30b811acf4d659f69d019260ad3ca
Call-ID: a723354c-f1a9-4071-b2a71eeeec8cd62b at 192.168.12.81
CSeq: 1314086103 BYE
User-Agent: Sphericall/8.0.0 Build/561
Max-Forwards: 70
Content-Length: 0
--end msg--
dlg044F90B4 Received Request msg BYE/cseq=1314086103 (rdata045DF09C)
tsx0454461C Transaction created for Request msg BYE/cseq=1314086103
(rdata045DF09C)
tsx0454461C Incoming Request msg BYE/cseq=1314086103 (rdata045DF09C) in
state Null
tsx0454461C State changed from Null to Trying, event=RX_MSG
dlg044F90B4 Transaction tsx0454461C state changed to Trying
endpoint Response msg 200/BYE/cseq=1314086103 (tdta05273458) created
dlg044F90B4 Sending Response msg 200/BYE/cseq=1314086103 (tdta05273458)
tsx0454461C Sending Response msg 200/BYE/cseq=1314086103 (tdta05273458)
in state Trying
sip_resolve.c Target '192.168.12.81:5060' type=UDP resolved to '
192.168.12.81:5060' type=UDP (UDP transport)
pjsua_core.c TX 369 bytes Response msg 200/BYE/cseq=1314086103
(tdta05273458) to UDP 192.168.12.81:5060:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.12.81:5060
;received=192.168.12.81;branch=z9hG4bK1415618c-b921-4d66-a80393079fcee148
Call-ID: a723354c-f1a9-4071-b2a71eeeec8cd62b at 192.168.12.81
From: <sip:4005@phoenix.local>;tag=8a595828-fa29-4d21-b370168266fd90fb
To: <sip:4916 at 192.168.12.81>;tag=20a30b811acf4d659f69d019260ad3ca
CSeq: 1314086103 BYE
Content-Length: 0
--end msg--
tsx0454461C State changed from Trying to Completed, event=TX_MSG
dlg044F90B4 Transaction tsx0454461C state changed to Completed
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.pjsip.org/pipermail/pjsip_lists.pjsip.org/attachments/20110829/34ccf354/attachment-0001.html>
