603 Declined on refer

Hi guys,

I’m having some trouble with referring calls, occasionally, 1 out of 10, calls get a 603 decline on refer.

I’m using a softphone SDK and freepbx version 4.211.64-8.

The scenario is that i’m using a server with a softphone to initiate a call, and when the call gets answered i forward it to client computer.

I’m in control of both the server, client and the phone which are being called. My wireshark traces shows that the server initiating the call gets a 603 declined when it refers to the client.

The wireshark on the client computer shows that the client doesn’t get notified of any incoming calls.

I have posted the debug log from one of the declines below:

[2014-05-08 11:16:10] DEBUG[2625][C-0000000e] chan_sip.c: Outgoing Call for 004521792466
[2014-05-08 11:16:10] DEBUG[2625][C-0000000e] chan_sip.c: Updating call counter for outgoing call
[2014-05-08 11:16:10] DEBUG[2625][C-0000000e] chan_sip.c: ** Our capability: (alaw) Video flag: False Text flag: False
[2014-05-08 11:16:10] DEBUG[2625][C-0000000e] chan_sip.c: ** Our prefcodec: (alaw)
[2014-05-08 11:16:10] DEBUG[2625][C-0000000e] chan_sip.c: – Done with adding codecs to SDP
[2014-05-08 11:16:10] DEBUG[2625][C-0000000e] chan_sip.c: Done building SDP. Settling with this capability: (alaw)
[2014-05-08 11:16:10] DEBUG[2625][C-0000000e] chan_sip.c: Initializing initreq for method INVITE - callid [email protected]:5060
[2014-05-08 11:16:10] DEBUG[2625][C-0000000e] chan_sip.c: Trying to put ‘INVITE sip:’ onto UDP socket destined for 178.21.248.30:5060
[2014-05-08 11:16:10] DEBUG[2380] manager.c: Examining event:
Event: Dial
Privilege: call,all
SubEvent: Begin
Channel: SIP/453-00000017
Destination: SIP/WilkeUni-tel-00000018
CallerIDNum: 63132979
CallerIDName:
ConnectedLineNum: 004521792466
ConnectedLineName: CID:63132979
UniqueID: 1399540569.28
DestUniqueID: 1399540570.29
Dialstring: WilkeUni-tel/004521792466

[2014-05-08 11:16:10] VERBOSE[2625][C-0000000e] app_dial.c: – Called SIP/WilkeUni-tel/004521792466
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: = Looking for Call ID: [email protected]:5060 (Checking To) --From tag as5a6db339 --To-tag

b27e1a1d33761e85846fc98f5f3a7e58.d488
[2014-05-08 11:16:10] DEBUG[2009][C-0000000e] chan_sip.c: Acked pending invite 102
[2014-05-08 11:16:10] DEBUG[2009][C-0000000e] chan_sip.c: Stopping retransmission on ‘[email protected]:5060’ of Request 102: Match Found
[2014-05-08 11:16:10] DEBUG[2009][C-0000000e] chan_sip.c: SIP response 407 to standard invite
[2014-05-08 11:16:10] DEBUG[2009][C-0000000e] chan_sip.c: Trying to put ‘ACK sip:004’ onto UDP socket destined for 178.21.248.30:5060
[2014-05-08 11:16:10] DEBUG[2009][C-0000000e] chan_sip.c: Auth attempt 1 on INVITE
[2014-05-08 11:16:10] DEBUG[2009][C-0000000e] chan_sip.c: ** Our capability: (alaw) Video flag: False Text flag: False
[2014-05-08 11:16:10] DEBUG[2009][C-0000000e] chan_sip.c: ** Our prefcodec: (alaw)
[2014-05-08 11:16:10] DEBUG[2009][C-0000000e] chan_sip.c: – Done with adding codecs to SDP
[2014-05-08 11:16:10] DEBUG[2009][C-0000000e] chan_sip.c: Done building SDP. Settling with this capability: (alaw)
[2014-05-08 11:16:10] DEBUG[2009][C-0000000e] chan_sip.c: Trying to put ‘INVITE sip:’ onto UDP socket destined for 178.21.248.30:5060
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: = Looking for Call ID: [email protected]:5060 (Checking To) --From tag as5a6db339 --To-tag
[2014-05-08 11:16:10] DEBUG[2009][C-0000000e] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘[email protected]:5060’

Request 103: Found
[2014-05-08 11:16:10] DEBUG[2009][C-0000000e] chan_sip.c: SIP response 100 to standard invite
[2014-05-08 11:16:10] DEBUG[2380] manager.c: Running action ‘Getvar’
[2014-05-08 11:16:10] DEBUG[2380] pbx.c: Result of ‘AJ_TRACE_ID’ is NULL
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: = Looking for Call ID: lmiowapntouqcrwaednrngtdmtfwcrapejbdpupfjgqaoapebv (Checking From) --From tag saffmfre --To-tag
[2014-05-08 11:16:10] DEBUG[2009] acl.c: For destination ‘10.216.170.35’, our source address is ‘10.216.170.178’.
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.216.170.178:5060
[2014-05-08 11:16:10] DEBUG[2009] netsock2.c: Splitting ‘10.216.170.35:15967’ into…
[2014-05-08 11:16:10] DEBUG[2009] netsock2.c: …host ‘10.216.170.35’ and port ‘15967’.
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: Allocating new SIP dialog for lmiowapntouqcrwaednrngtdmtfwcrapejbdpupfjgqaoapebv - OPTIONS (No RTP)
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: **** Received OPTIONS (3) - Command in SIP OPTIONS
[2014-05-08 11:16:10] DEBUG[2009] netsock2.c: Splitting ‘10.216.170.178’ into…
[2014-05-08 11:16:10] DEBUG[2009] netsock2.c: …host ‘10.216.170.178’ and port ‘’.
[2014-05-08 11:16:10] DEBUG[2009] netsock2.c: Splitting ‘10.216.170.178’ into…
[2014-05-08 11:16:10] DEBUG[2009] netsock2.c: …host ‘10.216.170.178’ and port ‘’.
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: Trying to put ‘SIP/2.0 200’ onto UDP socket destined for 10.216.170.35:15967
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: Allocating new SIP dialog for 58acf3f107669ba221ab2a8839feca3a@[::1]:5060 - OPTIONS (No RTP)
[2014-05-08 11:16:10] DEBUG[2009] acl.c: For destination ‘10.216.170.35’, our source address is ‘10.216.170.178’.
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.216.170.178:5060
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: SIP call-id changed from ‘58acf3f107669ba221ab2a8839feca3a@[::1]:5060’ to ‘[email protected]:5060’
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: Initializing initreq for method OPTIONS - callid [email protected]:5060
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: Trying to put ‘OPTIONS sip’ onto UDP socket destined for 10.216.170.35:15967
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: = Looking for Call ID: [email protected]:5060 (Checking To) --From tag as6c1960e5 --To-tag cejdmjyi
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: Stopping retransmission on ‘[email protected]:5060’ of Request 102: Match Found
[2014-05-08 11:16:10] DEBUG[2009] chan_sip.c: Destroying SIP dialog [email protected]:5060
[2014-05-08 11:16:10] DEBUG[2380] manager.c: Running action ‘Getvar’
[2014-05-08 11:16:10] DEBUG[2380] pbx.c: Result of ‘XMLNamespaceAssistedTransferTrackerId’ is NULL
[2014-05-08 11:16:10] DEBUG[2380] manager.c: Running action ‘Getvar’
[2014-05-08 11:16:10] DEBUG[2380] pbx.c: Result of ‘AJ_TRACE_ID’ is NULL
[2014-05-08 11:16:10] DEBUG[2380] manager.c: Running action ‘Getvar’
[2014-05-08 11:16:10] DEBUG[2380] pbx.c: Result of ‘XMLNamespaceAssistedTransferTrackerId’ is NULL
[2014-05-08 11:16:10] DEBUG[2380] manager.c: Running action ‘Getvar’
[2014-05-08 11:16:10] DEBUG[2380] pbx.c: Result of ‘AJ_TRACE_ID’ is NULL
[2014-05-08 11:16:10] DEBUG[2380] manager.c: Running action ‘Getvar’
[2014-05-08 11:16:10] DEBUG[2380] pbx.c: Result of ‘AJ_TRACE_ID’ is NULL
[2014-05-08 11:16:11] DEBUG[2026] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead
[2014-05-08 11:16:12] DEBUG[2026] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead
[2014-05-08 11:16:12] DEBUG[2009] chan_sip.c: Auto destroying SIP dialog ‘qevvadonxcxukrgfxscwhsipvajhtlbnnyhbmpqkttktlntlhk’
[2014-05-08 11:16:12] DEBUG[2009] chan_sip.c: Destroying SIP dialog qevvadonxcxukrgfxscwhsipvajhtlbnnyhbmpqkttktlntlhk
[2014-05-08 11:16:13] DEBUG[2026] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead
[2014-05-08 11:16:14] DEBUG[2009] chan_sip.c: Auto destroying SIP dialog ‘jxwsapodmqvjkwfbvdcmssdwwuauejpedkcpxbexurkrubpvlx’
[2014-05-08 11:16:14] DEBUG[2009] chan_sip.c: Destroying SIP dialog jxwsapodmqvjkwfbvdcmssdwwuauejpedkcpxbexurkrubpvlx
[2014-05-08 11:16:14] DEBUG[2009] rtp_engine.c: Destroyed RTP instance ‘0xb753f1c4’
[2014-05-08 11:16:16] DEBUG[2009] chan_sip.c: Auto destroying SIP dialog ‘[email protected]:5060’
[2014-05-08 11:16:16] DEBUG[2009] chan_sip.c: Destroying SIP dialog [email protected]:5060
[2014-05-08 11:16:16] DEBUG[2009] rtp_engine.c: Destroyed RTP instance ‘0xb73537e4’
[2014-05-08 11:16:17] DEBUG[2009] chan_sip.c: = Looking for Call ID: [email protected]:5060 (Checking To) --From tag as5a6db339 --To-tag as65940893
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on ‘[email protected]:5060’

Request 103: Found
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: SIP response 183 to standard invite
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: build_route: Record-Route hop: sip:178.21.248.8;lr;ftag=as5a6db339
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: build_route: Record-Route hop: sip:178.21.248.30;lr;ftag=as5a6db339;did=41c.59519dc2
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: Processing session-level SDP v=0… UNSUPPORTED OR FAILED.
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: Processing session-level SDP o=root 1990604758 1990604758 IN IP4 178.21.248.10… OK.
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: Processing session-level SDP s=Asterisk PBX 1.8.4.2… UNSUPPORTED OR FAILED.
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] netsock2.c: Splitting ‘178.21.248.32’ into…
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] netsock2.c: …host ‘178.21.248.32’ and port ‘’.
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: Processing session-level SDP c=IN IP4 178.21.248.32… OK.
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: Processing session-level SDP t=0 0… UNSUPPORTED OR FAILED.
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] rtp_engine.c: Setting payload 8 based on m type on 0xb6590d80
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] rtp_engine.c: Setting payload 101 based on m type on 0xb6590d80
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000… OK.
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000… OK.
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16… UNSUPPORTED OR FAILED.
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -… UNSUPPORTED OR FAILED.
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: Processing media-level (audio) SDP a=ptime:20… OK.
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: Processing media-level (audio) SDP a=sendrecv… OK.
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] res_rtp_asterisk.c: Setting RTCP address on RTP instance ‘0xb73d526c’
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] rtp_engine.c: Copying payload 8 from 0xb6590d80 to 0xb73d5418
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] rtp_engine.c: Copying payload 101 from 0xb6590d80 to 0xb73d5418
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance ‘0xb73d526c’
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: We’re settling with these formats: (alaw)
[2014-05-08 11:16:17] DEBUG[2009][C-0000000e] chan_sip.c: We have an owner, now see if we need to change this call
[2014-05-08 11:16:17] VERBOSE[2625][C-0000000e] app_dial.c: – SIP/WilkeUni-tel-00000018 is making progress passing it to SIP/453-00000017
[2014-05-08 11:16:17] DEBUG[2625][C-0000000e] chan_sip.c: Setting framing from config on incoming call
[2014-05-08 11:16:17] DEBUG[2625][C-0000000e] chan_sip.c: ** Our capability: (alaw) Video flag: False Text flag: True
[2014-05-08 11:16:17] DEBUG[2625][C-0000000e] chan_sip.c: ** Our prefcodec: (nothing)
[2014-05-08 11:16:17] DEBUG[2625][C-0000000e] chan_sip.c: – Done with adding codecs to SDP
[2014-05-08 11:16:17] DEBUG[2625][C-0000000e] chan_sip.c: Done building SDP. Settling with this capability: (alaw)
[2014-05-08 11:16:17] DEBUG[2625][C-0000000e] chan_sip.c: Trying to put ‘SIP/2.0 183’ onto UDP socket destined for 10.216.170.35:15967
[2014-05-08 11:16:17] DEBUG[2625][C-0000000e] res_rtp_asterisk.c: 0xb754f2a0 – Probation learning mode pass with source address 10.216.170.35:22187
[2014-05-08 11:16:17] DEBUG[2625][C-0000000e] chan_sip.c: Bogus frame of format ‘ulaw’ received from ‘SIP/453-00000017’!
[2014-05-08 11:16:17] DEBUG[2625][C-0000000e] chan_sip.c: Bogus frame of format ‘ulaw’ received from ‘SIP/453-00000017’!
[2014-05-08 11:16:26] DEBUG[2009] chan_sip.c: = Looking for Call ID: [email protected]:5060 (Checking To) --From tag as5a6db339 --To-tag as65940893
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Acked pending invite 103
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Stopping retransmission on ‘[email protected]:5060’ of Request 103: Match Found
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: SIP response 200 to standard invite
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Processing session-level SDP v=0… UNSUPPORTED OR FAILED.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Processing session-level SDP o=root 1990604758 1990604759 IN IP4 178.21.248.10… OK.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Processing session-level SDP s=Asterisk PBX 1.8.4.2… UNSUPPORTED OR FAILED.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] netsock2.c: Splitting ‘178.21.248.32’ into…
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] netsock2.c: …host ‘178.21.248.32’ and port ‘’.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Processing session-level SDP c=IN IP4 178.21.248.32… OK.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Processing session-level SDP t=0 0… UNSUPPORTED OR FAILED.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] rtp_engine.c: Setting payload 8 based on m type on 0xb6590d90
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] rtp_engine.c: Setting payload 101 based on m type on 0xb6590d90
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000… OK.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000… OK.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16… UNSUPPORTED OR FAILED.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -… UNSUPPORTED OR FAILED.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Processing media-level (audio) SDP a=ptime:20… OK.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Processing media-level (audio) SDP a=sendrecv… OK.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] res_rtp_asterisk.c: Setting RTCP address on RTP instance ‘0xb73d526c’
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] rtp_engine.c: Copying payload 8 from 0xb6590d90 to 0xb73d5418
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] rtp_engine.c: Copying payload 101 from 0xb6590d90 to 0xb73d5418
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance ‘0xb73d526c’
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: We’re settling with these formats: (alaw)
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: We have an owner, now see if we need to change this call
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Updating call counter for outgoing call
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: build_route: Record-Route hop: sip:178.21.248.8;lr;ftag=as5a6db339
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: build_route: Record-Route hop: sip:178.21.248.30;lr;ftag=as5a6db339;did=41c.59519dc2
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] netsock2.c: Splitting ‘178.21.248.10:5060’ into…
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] netsock2.c: …host ‘178.21.248.10’ and port ‘5060’.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] netsock2.c: Splitting ‘178.21.248.30’ into…
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] netsock2.c: …host ‘178.21.248.30’ and port ‘’.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Trying to put ‘ACK sip:217’ onto UDP socket destined for 178.21.248.30:5060
[2014-05-08 11:16:26] DEBUG[1994] devicestate.c: No provider found, checking channel drivers for SIP - WilkeUni-tel
[2014-05-08 11:16:26] DEBUG[1994] chan_sip.c: Checking device state for peer WilkeUni-tel
[2014-05-08 11:16:26] DEBUG[1994] devicestate.c: Changing state for SIP/WilkeUni-tel - state 1 (Not in use)
[2014-05-08 11:16:26] DEBUG[1994] devicestate.c: device ‘SIP/WilkeUni-tel’ state ‘1’
[2014-05-08 11:16:26] DEBUG[2038] app_queue.c: Device ‘SIP/WilkeUni-tel’ changed to state ‘1’ (Not in use) but we don’t care because they’re not a member of any queue.
[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: Newstate
Privilege: call,all
Channel: SIP/WilkeUni-tel-00000018
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 021792466
CallerIDName: CID:63132979
ConnectedLineNum: 63132979
ConnectedLineName:
Uniqueid: 1399540570.29

[2014-05-08 11:16:26] DEBUG[1987] cel_radius.c: Unable to create RADIUS record. CEL not recorded!
[2014-05-08 11:16:26] DEBUG[1987] res_odbc.c: odbc_release_obj2(0x86ee604) called (obj->txf = (nil))
[2014-05-08 11:16:26] VERBOSE[2625][C-0000000e] app_dial.c: – SIP/WilkeUni-tel-00000018 answered SIP/453-00000017
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] app.c: SIP/WilkeUni-tel-00000018 Original location: macro-dialout-trunk,s,1
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] pbx.c: Result of ‘ARG1’ is ‘none’
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] pbx.c: Launching ‘Set’
[2014-05-08 11:16:26] VERBOSE[2625][C-0000000e] pbx.c: – Executing [s@macro-setmusic:1] Set(“SIP/WilkeUni-tel-00000018”, “CHANNEL(musicclass)=none”) in new stack
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] app_macro.c: Executed application: Set
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] app.c: Macro exited with status 0
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] app.c: SIP/WilkeUni-tel-00000018 Ending location: macro-dialout-trunk,s,1
[2014-05-08 11:16:26] DEBUG[1994] devicestate.c: No provider found, checking channel drivers for SIP - 453
[2014-05-08 11:16:26] DEBUG[1994] chan_sip.c: Checking device state for peer 453
[2014-05-08 11:16:26] DEBUG[1994] devicestate.c: Changing state for SIP/453 - state 2 (In use)
[2014-05-08 11:16:26] DEBUG[1994] devicestate.c: device ‘SIP/453’ state ‘2’
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] chan_sip.c: SIP answering channel: SIP/453-00000017
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] res_rtp_asterisk.c: Setting the marker bit due to a source update
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] chan_sip.c: Setting framing from config on incoming call
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] chan_sip.c: ** Our capability: (alaw) Video flag: False Text flag: True
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] chan_sip.c: ** Our prefcodec: (nothing)
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] chan_sip.c: – Done with adding codecs to SDP
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] chan_sip.c: Done building SDP. Settling with this capability: (alaw)
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] chan_sip.c: Trying to put ‘SIP/2.0 200’ onto UDP socket destined for 10.216.170.35:15967
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] features.c: bridge answer set, chan answer set
[2014-05-08 11:16:26] DEBUG[2625][C-0000000e] features.c: Removing dialed interfaces datastore on SIP/WilkeUni-tel-00000018 since we’re bridging
[2014-05-08 11:16:26] DEBUG[2038] app_queue.c: Device ‘SIP/453’ changed to state ‘2’ (In use) but we don’t care because they’re not a member of any queue.
[2014-05-08 11:16:26] DEBUG[1987] cel_radius.c: Unable to create RADIUS record. CEL not recorded!
[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/453-00000017
Variable: DIALSTATUS
Value: ANSWER
Uniqueid: 1399540569.28

[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/453-00000017
Variable: DIALEDPEERNAME
Value: SIP/WilkeUni-tel-00000018
Uniqueid: 1399540569.28

[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/453-00000017
Variable: DIALEDPEERNUMBER
Value: WilkeUni-tel/004521792466
Uniqueid: 1399540569.28

[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/WilkeUni-tel-00000018
Variable: MACRO_EXTEN
Value: s
Uniqueid: 1399540570.29

[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/WilkeUni-tel-00000018
Variable: MACRO_CONTEXT
Value: macro-dialout-trunk
Uniqueid: 1399540570.29

[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/WilkeUni-tel-00000018
Variable: MACRO_PRIORITY
Value: 1
Uniqueid: 1399540570.29

[2014-05-08 11:16:26] DEBUG[2009] chan_sip.c: = Looking for Call ID: ufpsydbqfyupctxeqbilbufejfbuysiluxgyhbshpdupavunva (Checking From) --From tag sahixyal --To-tag as07f83f9f
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: **** Received REFER (9) - Command in SIP REFER
[2014-05-08 11:16:26] DEBUG[1987] res_odbc.c: odbc_release_obj2(0x86ee604) called (obj->txf = (nil))
[2014-05-08 11:16:26] DEBUG[1987] cel_radius.c: Unable to create RADIUS record. CEL not recorded!
[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/WilkeUni-tel-00000018
Variable: MACRO_DEPTH
Value: 1
Uniqueid: 1399540570.29

[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/WilkeUni-tel-00000018
Variable: ARG1
Value: none
Uniqueid: 1399540570.29

[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Trying to put ‘SIP/2.0 603’ onto UDP socket destined for 10.216.170.35:15967
[2014-05-08 11:16:26] DEBUG[1987] res_odbc.c: odbc_release_obj2(0x86ee604) called (obj->txf = (nil))
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: SIP message could not be handled, bad request: ufpsydbqfyupctxeqbilbufejfbuysiluxgyhbshpdupavunva
[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/WilkeUni-tel-00000018
Variable: MACRO_DEPTH
Value: 1
Uniqueid: 1399540570.29

[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: Newexten
Privilege: dialplan,all
Channel: SIP/WilkeUni-tel-00000018
Context: macro-setmusic
Extension: s
Priority: 1
Application: Set
AppData: CHANNEL(musicclass)=none
Uniqueid: 1399540570.29

[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/WilkeUni-tel-00000018
Variable: MACRO_DEPTH
Value: 0
Uniqueid: 1399540570.29

[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/453-00000017
Variable: BRIDGEPEER
Value: SIP/WilkeUni-tel-00000018
Uniqueid: 1399540569.28

[2014-05-08 11:16:26] DEBUG[2380] manager.c: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/WilkeUni-tel-00000018
Variable: BRIDGEPEER
Value: SIP/453-00000017
Uniqueid: 1399540570.29

[2014-05-08 11:16:26] DEBUG[2009] chan_sip.c: = Looking for Call ID: ufpsydbqfyupctxeqbilbufejfbuysiluxgyhbshpdupavunva (Checking From) --From tag sahixyal --To-tag as07f83f9f
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Got CANCEL or ACK on INVITE with transactions in between.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Stopping retransmission on ‘ufpsydbqfyupctxeqbilbufejfbuysiluxgyhbshpdupavunva’ of Response 2: Match Found
[2014-05-08 11:16:26] DEBUG[2009] chan_sip.c: = Looking for Call ID: ufpsydbqfyupctxeqbilbufejfbuysiluxgyhbshpdupavunva (Checking From) --From tag sahixyal --To-tag as07f83f9f
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: **** Received BYE (8) - Command in SIP BYE
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] netsock2.c: Splitting ‘10.216.170.35:15967’ into…
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] netsock2.c: …host ‘10.216.170.35’ and port ‘15967’.
[2014-05-08 11:16:26] DEBUG[2009][C-0000000e] chan_sip.c: Setting SIP_ALREADYGONE on dialog ufpsydbqfyupctxeqbilbufejfbuysiluxgyhbshpdupavunva

The client, server and pbx are all behind the same firewall.

Did i miss any relevant info?

Thanks for your time.

Mikael S.