[Home]

Summary:ASTERISK-13362: handle_request_invite: Call from '101334' to extension 's' rejected because extension not found - FreeBSD sparc64
Reporter:Serhiy Trylis (tryk)Labels:
Date Opened:2009-01-14 04:20:35.000-0600Date Closed:2011-06-07 14:07:54
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Incoming calls from external peers are rejected - looks like Asterisk is unable to lookup the extension in dialplan on Sparc64/FreeBSD 7.0-RELEASE build. Error message:

[Jan 14 12:09:58] NOTICE[78353]: chan_sip.c:17032 handle_request_invite: Call from '101334' to extension 's' rejected because extension not found.

This is not a config problem, as the same configuration works perfectly on i386 build.

****** ADDITIONAL INFORMATION ******

Version: Asterisk 1.6.0.3-rc1 built by root @ quebab.lost.net.ua on a sparc64 running FreeBSD on 2009-01-06 16:31:40 UTC

Error message:


sip.conf:

register => 101334:*****@ipshka.com
auth=101334:*******@ipshka.com

[ipshka]
secret = *********
defaultuser = 101334
trunkname = ipshka
type = friend
callerid =
hasexten = no
hassip = yes
hasiax = no
host = ipshka.com
context = providersin
insecure = invite,port
fromuser = 101334
fromdomain = ipshka.com
disallow=all
allow = alaw
allow = ulaw
allow = g729
nat = no
canreinvite = nonat
dtmfmode = info

dialplan show:

...
[ Context 'providersin' created by 'pbx_config' ]
 '101334' =>       1. Dial(SIP/6466)                             [pbx_config]
 'i' =>            1. Dial(SIP/6466)                             [pbx_config]
 's' =>            1. Dial(SIP/6466)                             [pbx_config]
 '_.' =>           1. Dial(SIP/6466)                             [pbx_config]
...

(SIP-peer 6466 is configured, registered and works well).

Comments:By: Leif Madsen (lmadsen) 2009-01-20 14:39:58.000-0600

Assigning this issue to mvanbaak to determine if there is anything he can do with it, or where the issue may lie.

If you are not able to do anything with this issue, please unassign yourself and set it back to status of 'New'.

Thanks!
By: Michiel van Baak (mvanbaak) 2009-01-21 01:58:05.000-0600

Since this is working fine for me on OpenBSD 4.4 amd64 and FreeBSD 7.0 amd64 there's not a lot I can do.

I have no experience with sparc64 at the moment, so not really sure where to look.
By: Tilghman Lesher (tilghman) 2009-01-21 02:33:40.000-0600

Unmarking as major, as this is clearly a platform issue.
By: Tilghman Lesher (tilghman) 2009-01-21 02:35:29.000-0600

tryk:  Please enable full DEBUG level logging and upload the related section of the resulting log.
By: Serhiy Trylis (tryk) 2009-01-22 14:39:32.000-0600

There is no debug messages.. Or am I doing something wrong?

(I've added a small personal patch to print out context name).

[root@quebab /home/tryk]# asterisk -rdvvvvvvvvvvvvvvvvvvvvvv
Asterisk 1.6.0.3-rc1, Copyright (C) 1999 - 2008 Digium, Inc. and others.
Created by Mark Spencer <markster@digium.com>
Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details.
This is free software, with components licensed under the GNU General Public
License version 2 and other licenses; you are welcome to redistribute it under
certain conditions. Type 'core show license' for details.
=========================================================================
 == Parsing '/usr/local/etc/asterisk/asterisk.conf': Parsing /usr/local/etc/asterisk/asterisk.conf
 == Found
 == Parsing '/usr/local/etc/asterisk/extconfig.conf': Parsing /usr/local/etc/asterisk/extconfig.conf
 == Found
Connected to Asterisk 1.6.0.3-rc1 currently running on quebab (pid = 5181)
Verbosity is at least 28
Core debug is at least 10
[Jan 22 22:36:49] NOTICE[5181]: chan_sip.c:17032 handle_request_invite: Call from '101334' to extension 's' rejected because extension not found in context 'providersin'.
quebab*CLI>
By: Tilghman Lesher (tilghman) 2009-01-25 18:16:53.000-0600

tryk:  please check that you've enabled "debug" in logger.conf for "console".
By: Serhiy Trylis (tryk) 2009-01-26 08:12:16.000-0600

*****************************************************************************
*** The issue has been solved by addind IP-address as domain= in sip.conf ***
*****************************************************************************

Sorry for a stupid "bug".

[Jan 26 16:00:15] DEBUG[2332]: chan_sip.c:6062 find_call: = Found Their Call ID: MTk3ZTM1OTU4NGM3YTFhZTJjYmVjMGQzNWQ2N2Y4NTA. Their Tag 6631e030 Our tag: as4d942390
[Jan 26 16:00:15] DEBUG[2332]: chan_sip.c:18496 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER
[Jan 26 16:00:15] DEBUG[2332]: chan_sip.c:18515 handle_incoming: Ignoring SIP message because of retransmit (REGISTER Seqno 384, ours 384)
[Jan 26 16:00:15] DEBUG[2332]: chan_sip.c:2589 __sip_xmit: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.0.251:64445
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:6062 find_call: = Found Their Call ID: MTk3ZTM1OTU4NGM3YTFhZTJjYmVjMGQzNWQ2N2Y4NTA. Their Tag 6631e030 Our tag: as4d942390
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:18496 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:18515 handle_incoming: Ignoring SIP message because of retransmit (REGISTER Seqno 384, ours 384)
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:2589 __sip_xmit: Trying to put 'SIP/2.0 40' onto UDP socket destined for 192.168.0.251:64445
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:6062 find_call: = No match Their Call ID: MTk3ZTM1OTU4NGM3YTFhZTJjYmVjMGQzNWQ2N2Y4NTA. Their Tag 6631e030 Our tag: as4d942390
[Jan 26 16:00:19] DEBUG[2332]: acl.c:490 ast_ouraddrfor: Found IP address for this socket
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:3915 do_setnat: Setting NAT on RTP to Off
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:3919 do_setnat: Setting NAT on VRTP to Off
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:5996 sip_alloc: Allocating new SIP dialog for 99619335-8eaa-4481-9841-944329529ba6 - INVITE (With RTP)
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:18496 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:3915 do_setnat: Setting NAT on RTP to Off
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:3919 do_setnat: Setting NAT on VRTP to Off
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:7129 process_sdp: We're settling with these formats: 0xc (ulaw|alaw)
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:17004 handle_request_invite: Checking SIP call limits for device 101334
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:4499 update_call_counter: Updating call counter for incoming call
[Jan 26 16:00:19] DEBUG[2332]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/ipshka
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:10885 get_destination: Got SIP INVITE to non-local domain '212.109.45.71'; refusing request.
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:2589 __sip_xmit: Trying to put 'SIP/2.0 40' onto UDP socket destined for 193.28.184.13:5060
[Jan 26 16:00:19] DEBUG[2332]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for SIP - ipshka
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:19633 sip_devicestate: Checking device state for peer ipshka
[Jan 26 16:00:19] DEBUG[2332]: devicestate.c:441 do_state_change: Changing state for SIP/ipshka - state 2 (In use)
[Jan 26 16:00:19] NOTICE[2332]: chan_sip.c:17032 handle_request_invite: Call from '101334' to extension 's' rejected because extension not found in context 'providersin'.
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:4499 update_call_counter: Updating call counter for incoming call
[Jan 26 16:00:19] DEBUG[2332]: devicestate.c:450 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/ipshka
[Jan 26 16:00:19] DEBUG[2332]: devicestate.c:323 _ast_device_state: No provider found, checking channel drivers for SIP - ipshka
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:19633 sip_devicestate: Checking device state for peer ipshka
[Jan 26 16:00:19] DEBUG[2332]: devicestate.c:441 do_state_change: Changing state for SIP/ipshka - state 1 (Not in use)
[Jan 26 16:00:19] DEBUG[2332]: app_queue.c:767 handle_statechange: Device 'SIP/ipshka' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jan 26 16:00:19] DEBUG[2332]: app_queue.c:767 handle_statechange: Device 'SIP/ipshka' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:6062 find_call: = Found Their Call ID: 99619335-8eaa-4481-9841-944329529ba6 Their Tag bf60f912-52f3-425d-aac9-23bfc7c447e3 Our tag: as5d17be1b
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:18496 handle_incoming: **** Received ACK (6) - Command in SIP ACK
[Jan 26 16:00:19] DEBUG[2332]: chan_sip.c:3066 __sip_ack: Stopping retransmission on '99619335-8eaa-4481-9841-944329529ba6' of Response 17049: Match Found
By: Leif Madsen (lmadsen) 2009-01-27 14:14:04.000-0600

Closed due to reporter fixing a configuration problem. Thanks for following up!