500 Internal Server Error after REFER

Hi,

since we’ve upgraded from Asterisk 1.8 (I know, I know) to 13.14, our receptionists cannot perform blind transfers anymore.

In the following trace, 10.11.255.248 is the internal phone (an Aastra 6757i) and 10.11.4.1 is the Asterisk server.

There is an ongoing call between the internal extension (sip:test-host@<SIP_DOMAIN>) and the external caller (sip:<EXTERNAL_NUMBER>@10.11.4.1). The call should be transferred to another internal extension (sip:9064@<SIP_DOMAIN>).

We can see that Asterisk responds with a 202 ACCEPTED message to the initial REFER, but follows immediately with a NOTIFY that contains “SIP/2.0 500 Internal Server Error”. At this moment, the internal phone shows “Transfer cancelled”.

17:53:23.647438 IP (tos 0x68, ttl 64, id 5168, offset 0, flags [none], proto UDP (17), length 793)
    10.11.255.248.5060 > 10.11.4.1.5060: [udp sum ok] SIP, length: 765
	REFER sip:<EXTERNAL_NUMBER>@10.11.4.1:5060 SIP/2.0
	Via: SIP/2.0/UDP 10.11.255.248:5060;branch=z9hG4bK50d47869352ef6be0
	Route: <sip:<SIP_DOMAIN>;lr>
	Max-Forwards: 70
	From: "<INTERNAL_NUMBER>" <sip:test-host@<SIP_DOMAIN>>;tag=62f489625f
	To: <sip:<EXTERNAL_NUMBER>@<SIP_DOMAIN>;user=phone>;tag=as6e181d1d
	Call-ID: 06d8e6955fa413e3
	CSeq: 20300 REFER
	Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO
	Allow-Events: talk, hold, conference, LocalModeStatus
	Contact: "<INTERNAL_NUMBER>" <sip:test-host@10.11.255.248:5060;transport=udp>;+sip.instance="<urn:uuid:00000000-0000-1000-8000-00085D3ED8AD>"
	Refer-To: <sip:9064@<SIP_DOMAIN>>
	Referred-By: <sip:test-host@<SIP_DOMAIN>>
	Supported: path
	User-Agent: Aastra 57i/3.3.1.4305
	Content-Length: 0
	
17:53:23.647688 IP (tos 0x60, ttl 64, id 43093, offset 0, flags [none], proto UDP (17), length 541)
    10.11.4.1.5060 > 10.11.255.248.5060: [bad udp cksum 0x1a2a -> 0x387e!] SIP, length: 513
	SIP/2.0 202 Accepted
	Via: SIP/2.0/UDP 10.11.255.248:5060;branch=z9hG4bK50d47869352ef6be0;received=10.11.255.248
	From: "<INTERNAL_NUMBER>" <sip:test-host@<SIP_DOMAIN>>;tag=62f489625f
	To: <sip:<EXTERNAL_NUMBER>@<SIP_DOMAIN>;user=phone>;tag=as6e181d1d
	Call-ID: 06d8e6955fa413e3
	CSeq: 20300 REFER
	Server: Asterisk PBX 13.14.1~dfsg-2+deb9u3
	Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
	Supported: replaces, timer
	Contact: <sip:<EXTERNAL_NUMBER>@10.11.4.1:5060>
	Content-Length: 0
	
17:53:23.648052 IP (tos 0x60, ttl 64, id 43094, offset 0, flags [none], proto UDP (17), length 719)
    10.11.4.1.5060 > 10.11.255.248.5060: [bad udp cksum 0x1adc -> 0x5a15!] SIP, length: 691
	NOTIFY sip:test-host@10.11.255.248:5060;transport=udp SIP/2.0
	Via: SIP/2.0/UDP 10.11.4.1:5060;branch=z9hG4bK0ef7bffb
	Max-Forwards: 70
	From: <sip:<EXTERNAL_NUMBER>@<SIP_DOMAIN>;user=phone>;tag=as6e181d1d
	To: "<INTERNAL_NUMBER>" <sip:test-host@<SIP_DOMAIN>>;tag=62f489625f
	Contact: <sip:<EXTERNAL_NUMBER>@10.11.4.1:5060>
	Call-ID: 06d8e6955fa413e3
	CSeq: 102 NOTIFY
	User-Agent: Asterisk PBX 13.14.1~dfsg-2+deb9u3
	Event: refer;id=20300
	Subscription-state: terminated;reason=noresource
	Content-Type: message/sipfrag;version=2.0
	Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
	Supported: replaces, timer
	Content-Length: 35
	
	SIP/2.0 500 Internal Server Error

17:53:23.718268 IP (tos 0x68, ttl 64, id 5170, offset 0, flags [none], proto UDP (17), length 484)
    10.11.255.248.5060 > 10.11.4.1.5060: [udp sum ok] SIP, length: 456
	SIP/2.0 200 OK
	Via: SIP/2.0/UDP 10.11.4.1:5060;branch=z9hG4bK0ef7bffb
	From: <sip:<EXTERNAL_NUMBER>@<SIP_DOMAIN>;user=phone>;tag=as6e181d1d
	To: "<INTERNAL_NUMBER>" <sip:test-host@<SIP_DOMAIN>>;tag=62f489625f
	Call-ID: 06d8e6955fa413e3
	CSeq: 102 NOTIFY
	Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO
	Allow-Events: talk, hold, conference, LocalModeStatus
	Server: Aastra 57i/3.3.1.4305
	Supported: path
	Content-Length: 0

The only related entry I see in the Asterisk log is

[Jun 15 17:53:23] NOTICE[381][C-0000047a] chan_sip.c: Got OK on REFER Notify message

I thought that the 500 might originate from our upstream VoIP provider, but a packet trace on that end shows that the REFER never goes there, and no messages on that end show 500 status.

Can anyone give me some pointers what is going on here? I’ll gladly provide more details if required. Thanks a lot!

1 Like

You would need to provide the complete Asterisk console output with debug (debug to console in logger.conf and core set debug 9). That may provide information about what is going on.

1 Like

Thanks for the reply! I tried to produce debug output as explained by you.

As soon as I initiate the transfer on the phone, I get a lot of the following lines:

[Jun 22 19:21:12] DEBUG[27661][C-00000004]: res_rtp_asterisk.c:3571 ast_rtp_write: No remote address on RTP instance '0x7f4aa800b360' so dropping frame

These entries then follow that I assume relate to the transfer:

[Jun 22 19:21:12] DEBUG[24789][C-00000004]: chan_sip.c:28642 handle_incoming: **** Received REFER (9) - Command in SIP REFER
[Jun 22 19:21:12] DEBUG[24789][C-00000004]: chan_sip.c:3753 __sip_xmit: Trying to put 'SIP/2.0 202' onto UDP socket destined for 10.11.255.248:5060
[Jun 22 19:21:12] DEBUG[24789][C-00000004]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.11.255.248:5060' into...
[Jun 22 19:21:12] DEBUG[24789][C-00000004]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.11.255.248' and port '5060'.
[Jun 22 19:21:12] DEBUG[24789][C-00000004]: chan_sip.c:3753 __sip_xmit: Trying to put 'NOTIFY sip:' onto UDP socket destined for 10.11.255.248:5060
[Jun 22 19:21:12] DEBUG[24789][C-00000004]: chan_sip.c:28945 handle_request_do: SIP message could not be handled, bad request: e513863665b16b87                    

But nothing else.
The again lots of the “dropping frame entries”, and finally the phone picks up the call again after the failed transfer:

[Jun 22 19:21:17] DEBUG[24789][C-00000004]: chan_sip.c:28642 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Jun 22 19:21:17] DEBUG[24789][C-00000004]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.11.255.248:5060' into...
[Jun 22 19:21:17] DEBUG[24789][C-00000004]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.11.255.248' and port '5060'.
[Jun 22 19:21:17] DEBUG[24789][C-00000004]: chan_sip.c:10261 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[Jun 22 19:21:17] DEBUG[24789][C-00000004]: chan_sip.c:10261 process_sdp: Processing session-level SDP o=MxSIP 0 3 IN IP4 10.11.255.248... OK.
[Jun 22 19:21:17] DEBUG[24789][C-00000004]: chan_sip.c:10261 process_sdp: Processing session-level SDP s=SIP Call... UNSUPPORTED OR FAILED.
[Jun 22 19:21:17] DEBUG[24789][C-00000004]: netsock2.c:172 ast_sockaddr_split_hostport: Splitting '10.11.255.248' into...
[Jun 22 19:21:17] DEBUG[24789][C-00000004]: netsock2.c:226 ast_sockaddr_split_hostport: ...host '10.11.255.248' and port ''.

and so on.

I’d be happy to provide more information if required.