[Home]

Summary:ASTERISK-19898: OriginateResponse event is received with Reason 3, 'remote end is ringing', while remote end destination is unreachable
Reporter:Modulus (modulus)Labels:
Date Opened:2012-05-22 13:40:49Date Closed:2018-01-02 08:44:19.000-0600
Priority:MinorRegression?
Status:Closed/CompleteComponents:Core/ManagerInterface
Versions:1.8.10.1 Frequency of
Occurrence		Constant
Related
Issues:
Environment:GNU/Linux (Debian Squeeze with kernel 2.6.32-5-686) on i686Attachments:
Description:Steps to reproduce:
1) Remove default gw from the machine running asterisk, so that all remote destinations become unreachable.
2) Originate a call through AMI (SIP channel 'SIP/somepeer/XXXXXXXXXX')
3) Listen for OriginateResponse event

OriginateResponse event is received with *Reason* '3', which according to frame.h means 'Remote end is ringing'.
However, remote end has never been in ringing state because it's unreachable.

Perhaps an interesting note here is that *Hangup cause* '3' maps to 'NO_ROUTE_DESTINATION', which seems to match exactly the situation.
Was that '3' value meant to be assigned to the hangup cause instead of being assigned to the reason/frame type code?
The Hangup event that comes before OriginateResponse event holds a cause value of '0' (cause-txt:unknown).

An excerpt from logs follows:
{noformat}
[May 22 20:01:53] DEBUG[2741] manager.c: Running action 'Originate'
[May 22 20:01:53] DEBUG[2747] chan_sip.c: Asked to create a SIP channel with formats: 0x40 (slin)
[May 22 20:01:53] DEBUG[2747] chan_sip.c: Allocating new SIP dialog for 53fa663c1a81d7950d7f2d2c783ec667@127.0.1.1:5060 - INVITE (No RTP)
[May 22 20:01:53] DEBUG[2747] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 22 20:01:53] DEBUG[2747] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 'somepeer' AND host = 'dynamic'
[May 22 20:01:53] DEBUG[2747] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 22 20:01:53] DEBUG[2747] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 'somepeer'
[May 22 20:01:53] DEBUG[2747] chan_sip.c: -REALTIME- peer built. Name: somepeer. Peer objects: 1
[May 22 20:01:53] DEBUG[2747] netsock2.c: Splitting 'sipserver.example.org' into...
[May 22 20:01:53] DEBUG[2747] netsock2.c: ...host 'sipserver.example.org' and port ''.
[May 22 20:01:53] DEBUG[2747] netsock2.c: Splitting 'sipserver.example.org' into...
[May 22 20:01:53] DEBUG[2747] netsock2.c: ...host 'sipserver.example.org' and port ''.
[May 22 20:01:53] VERBOSE[2747] srv.c:        > ast_get_srv: SRV lookup for '_sip._udp.sipserver.example.org' mapped to host sipserver.example.org, port 5060
[May 22 20:01:53] DEBUG[2747] netsock2.c: Splitting 'sipserver.example.org' into...
[May 22 20:01:53] DEBUG[2747] netsock2.c: ...host 'sipserver.example.org' and port ''.
[May 22 20:01:53] DEBUG[2747] netsock2.c: Splitting 'sipserver.example.org' into...
[May 22 20:01:53] DEBUG[2747] netsock2.c: ...host 'sipserver.example.org' and port ''.
[May 22 20:01:53] VERBOSE[2747] dnsmgr.c:        > doing dnsmgr_lookup for 'sipserver.example.org'
[May 22 20:01:53] VERBOSE[2747] srv.c:        > ast_get_srv: SRV lookup for '_sip._udp.sipserver.example.org' mapped to host sipserver.example.org, port 5060
[May 22 20:01:53] DEBUG[2747] netsock2.c: Splitting 'sipserver.example.org' into...
[May 22 20:01:53] DEBUG[2747] netsock2.c: ...host 'sipserver.example.org' and port ''.
[May 22 20:01:53] DEBUG[2747] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 22 20:01:53] DEBUG[2747] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 22 20:01:53] DEBUG[2747] chan_sip.c: -REALTIME- loading peer from database to memory. Name: somepeer. Peer objects: 1
[May 22 20:01:53] DEBUG[2747] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x9c8fbd8'
[May 22 20:01:53] DEBUG[2747] res_rtp_asterisk.c: Allocated port 15266 for RTP instance '0x9c8fbd8'
[May 22 20:01:53] DEBUG[2747] rtp_engine.c: RTP instance '0x9c8fbd8' is setup and ready to go
[May 22 20:01:53] DEBUG[2747] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x9c8fbd8'
[May 22 20:01:53] VERBOSE[2747] netsock2.c:   == Using SIP RTP CoS mark 5
[May 22 20:01:53] DEBUG[2747] chan_sip.c: Setting NAT on RTP to On
[May 22 20:01:53] WARNING[2747] acl.c: Cannot connect
[May 22 20:01:53] DEBUG[2747] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 127.0.1.1:5060
[May 22 20:01:53] DEBUG[2747] chan_sip.c: *** Our native formats are 0x8 (alaw)
[May 22 20:01:53] DEBUG[2747] chan_sip.c: *** Joint capabilities are 0x0 (nothing)
[May 22 20:01:53] DEBUG[2747] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw)
[May 22 20:01:53] DEBUG[2747] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw)
[May 22 20:01:53] DEBUG[2747] chan_sip.c: *** Our preferred formats from the incoming channel are 0x40 (slin)
[May 22 20:01:53] DEBUG[2747] chan_sip.c: This channel will not be able to handle video.
[May 22 20:01:53] DEBUG[2747] chan_sip.c: Outgoing Call for XXXXXXXXXX
[May 22 20:01:53] DEBUG[2747] chan_sip.c: Updating call counter for outgoing call
[May 22 20:01:53] DEBUG[2747] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: False Text flag: False
[May 22 20:01:53] DEBUG[2747] chan_sip.c: ** Our prefcodec: 0x40 (slin)
[May 22 20:01:53] DEBUG[2747] chan_sip.c: -- Done with adding codecs to SDP
[May 22 20:01:53] DEBUG[2747] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[May 22 20:01:53] DEBUG[2747] chan_sip.c: Initializing initreq for method INVITE - callid 4cdc35d23bae90af1e6089a91af95f97@127.0.1.1:5060
[May 22 20:01:53] DEBUG[2747] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for a.b.c.d:5060
[May 22 20:01:53] WARNING[2747] chan_sip.c: sip_xmit of 0x9c9d290 (len 887) to a.b.c.d:5060 returned -2: Network is unreachable
[May 22 20:01:53] ERROR[2747] chan_sip.c: Serious Network Trouble; __sip_xmit returns error for pkt data
[May 22 20:01:53] DEBUG[2741] manager.c: Examining event:
Event: Newchannel
Privilege: call,all
Channel: SIP/somepeer-00000018
ChannelState: 0
ChannelStateDesc: Down
CallerIDNum:
CallerIDName:
AccountCode:
Exten:
Context:
Uniqueid: 1337706113.24


[May 22 20:01:53] DEBUG[2741] manager.c: Examining event:
Event: NewAccountCode
Privilege: call,all
Channel: SIP/somepeer-00000018
Uniqueid: 1337706113.24
AccountCode:
OldAccountCode:


[May 22 20:01:53] DEBUG[2741] manager.c: Examining event:
Event: NewCallerid
Privilege: call,all
Channel: SIP/somepeer-00000018
CallerIDNum: 2000
CallerIDName: mytest
Uniqueid: 1337706113.24
CID-CallingPres: 0 (Presentation Allowed, Not Screened)


[May 22 20:01:53] DEBUG[1278] devicestate.c: No provider found, checking channel drivers for SIP - somepeer
[May 22 20:01:53] DEBUG[1278] chan_sip.c: Checking device state for peer somepeer
[May 22 20:01:53] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 22 20:01:53] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 'somepeer' AND host = 'dynamic'
[May 22 20:01:53] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 22 20:01:53] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 'somepeer' AND host = 'dynamic'
[May 22 20:01:53] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 22 20:01:53] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 22 20:01:53] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 'somepeer'
[May 22 20:01:53] DEBUG[1278] chan_sip.c: -REALTIME- peer built. Name: somepeer. Peer objects: 2
[May 22 20:01:53] DEBUG[1278] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 22 20:01:53] DEBUG[1278] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 22 20:01:53] DEBUG[1278] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 22 20:01:53] DEBUG[1278] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 22 20:01:53] DEBUG[1278] chan_sip.c: -REALTIME- loading peer from database to memory. Name: somepeer. Peer objects: 2
[May 22 20:01:53] DEBUG[1278] chan_sip.c: Destroying SIP peer somepeer
[May 22 20:01:53] DEBUG[1278] chan_sip.c: -REALTIME- peer Destroyed. Name: somepeer. Realtime Peer objects: 1
[May 22 20:01:53] DEBUG[1278] devicestate.c: Changing state for SIP/somepeer - state 5 (Unavailable)
[May 22 20:01:53] DEBUG[1278] devicestate.c: device 'SIP/somepeer' state '5'
[May 22 20:01:53] DEBUG[1328] app_queue.c: Device 'SIP/somepeer' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[May 22 20:02:23] DEBUG[2747] channel.c: Hanging up channel 'SIP/somepeer-00000018'
[May 22 20:02:23] DEBUG[2747] chan_sip.c: Hanging up zombie call. Be scared.
[May 22 20:02:23] DEBUG[2747] chan_sip.c: Updating call counter for outgoing call
[May 22 20:02:23] DEBUG[2747] chan_sip.c: Hanging up channel in state Down (not UP)
[May 22 20:02:23] DEBUG[2747] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x9c8fbd8'
[May 22 20:02:23] DEBUG[1278] devicestate.c: No provider found, checking channel drivers for SIP - somepeer
[May 22 20:02:23] DEBUG[1278] chan_sip.c: Checking device state for peer somepeer
[May 22 20:02:23] DEBUG[2741] manager.c: Examining event:
Event: Hangup
Privilege: call,all
Channel: SIP/somepeer-00000018
Uniqueid: 1337706113.24
CallerIDNum: 2000
CallerIDName: mytest
ConnectedLineNum: 2000
ConnectedLineName: mytest
Cause: 0
Cause-txt: Unknown


[May 22 20:02:23] DEBUG[2741] manager.c: Examining event:
Event: OriginateResponse
Privilege: call,all
ActionID: modfax-00000004
Response: Failure
Channel: SIP/somepeer/XXXXXXXXXX
Context: MYTEST
Exten: s
Reason: 3
Uniqueid: <null>
CallerIDNum: 2000
CallerIDName: mytest


[May 22 20:02:23] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 22 20:02:23] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 'somepeer' AND host = 'dynamic'
[May 22 20:02:23] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 22 20:02:23] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 'somepeer'
[May 22 20:02:23] DEBUG[1278] chan_sip.c: -REALTIME- peer built. Name: somepeer. Peer objects: 2
[May 22 20:02:23] DEBUG[1278] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 22 20:02:23] DEBUG[1278] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 22 20:02:23] DEBUG[1278] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 22 20:02:23] DEBUG[1278] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 22 20:02:23] DEBUG[1278] chan_sip.c: -REALTIME- loading peer from database to memory. Name: somepeer. Peer objects: 2
[May 22 20:02:23] DEBUG[1278] chan_sip.c: Destroying SIP peer somepeer
[May 22 20:02:23] DEBUG[1278] chan_sip.c: -REALTIME- peer Destroyed. Name: somepeer. Realtime Peer objects: 1
[May 22 20:02:23] DEBUG[1278] devicestate.c: Changing state for SIP/somepeer - state 5 (Unavailable)
[May 22 20:02:23] DEBUG[1278] devicestate.c: device 'SIP/somepeer' state '5'
[May 22 20:02:23] DEBUG[1278] devicestate.c: No provider found, checking channel drivers for SIP - somepeer
[May 22 20:02:23] DEBUG[1278] chan_sip.c: Checking device state for peer somepeer
[May 22 20:02:23] DEBUG[1328] app_queue.c: Device 'SIP/somepeer' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[May 22 20:02:23] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 22 20:02:23] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 'somepeer' AND host = 'dynamic'
[May 22 20:02:23] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Connection okay.
[May 22 20:02:23] DEBUG[1278] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_peers WHERE name = 'somepeer'
[May 22 20:02:23] DEBUG[1278] chan_sip.c: -REALTIME- peer built. Name: somepeer. Peer objects: 2
[May 22 20:02:23] DEBUG[1278] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 22 20:02:23] DEBUG[1278] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 22 20:02:23] DEBUG[1278] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port.
[May 22 20:02:23] DEBUG[1278] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port.
[May 22 20:02:23] DEBUG[1278] chan_sip.c: -REALTIME- loading peer from database to memory. Name: somepeer. Peer objects: 2
[May 22 20:02:23] DEBUG[1278] chan_sip.c: Destroying SIP peer somepeer
[May 22 20:02:23] DEBUG[1278] chan_sip.c: -REALTIME- peer Destroyed. Name: somepeer. Realtime Peer objects: 1
[May 22 20:02:23] DEBUG[1278] devicestate.c: Changing state for SIP/somepeer - state 5 (Unavailable)
[May 22 20:02:23] DEBUG[1278] devicestate.c: device 'SIP/somepeer' state '5'
[May 22 20:02:23] DEBUG[1328] app_queue.c: Device 'SIP/somepeer' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
{noformat}
Comments:By: Joshua C. Colp (jcolp) 2017-12-19 05:51:00.825-0600

Are you still experiencing this as a problem under recent supported versions of Asterisk?
By: Asterisk Team (asteriskteam) 2018-01-02 08:44:19.661-0600

Suspended due to lack of activity. This issue will be automatically re-opened if the reporter posts a comment. If you are not the reporter and would like this re-opened please create a new issue instead. If the new issue is related to this one a link will be created during the triage process. Further information on issue tracker usage can be found in the Asterisk Issue Guidlines [1].

[1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines