[asterisk-dev] Start testing with res_sip

Thu Jun 20 15:27:25 CDT 2013

Hi,

> [snipped]
>
>
>> [Jun 20 16:49:59] DEBUG[11844]: res_sip_endpoint_identifier_user.c:104
>> username_identify: Retrieved endpoint 101
>> [Jun 20 16:49:59] DEBUG[11844]: res_sip_session.c:1438
>> handle_outgoing_response: Response is 404 Not Found
>
>
> The fact that the handle_outgoing_response() message printed, but there was
> not a handle_outgoing() message printed before, means that the 404 was sent
> as a result of a call to ast_sip_session_send_response(). There are two ways
> I know of that that response may be sent:
>
> 1) If the request destination does not exist. In this case, if
> extensions.conf does not have 1000 at testing.
> 2) If whatever occurred at 1001 at testing resulted in a hangup cause of either
> AST_CAUSE_UNALLOCATED, AST_CAUSE_NO_ROUTE_DESTINATION, or
> AST_CAUSE_NO_ROUTE_TRANSIT_NET.
>
> If one one of the two conditions above were met, that would help to explain
> the source of the 404. Most likely, we're dealing with case 1 since I would
> expect to have seen Asterisk send a 100 Trying if control reached the
> dialplan.
>
> What is not explained is why authentication appears to be bypassed
> completely. Since your CLI output indicates that
> res_sip_authenticator_digest.so is loaded, it should have noticed that
> endpoint 101 has authentication configured and sent a challenge long before
> we would be checking the destination of the request. We can see from your
> output that endpoint 101 was properly identified when the call came in. The
> only reason authentication would be bypassed is if we think the endpoint has
> no authentication configured. I would check startup messages and see if
> there were any warnings or errors printed with regards to reading
> configuration. Unfortunately, we don't have a CLI command at the moment to
> show an endpoint's configuration (it's in a branch though). The only way
> you'll be able to check on runtime state of an endpoint would be to use a
> debugger. The other thing you can look for are error and warning messages on
> startup pertaining to res_sip and its related modules. Perhaps there is
> something there that could shed some light on the problem.
>
> For what it's worth, Joshua Colp and I have both taken your configuration
> and set it up locally and had it work fine. Here's a SIP trace where I used
> your configuration. The only difference is that I used a Digium D40 phone to
> place the call instead of Bria (and of course IP addresses are different).
>

I started over, and installed from fresh. Here's what I did:

Standard Ubuntu 12.04 download+install from Parallels
Update all software - reboot.

sudo apt-get install vim build-essential libncurses-dev  uuid-dev
libjansson-dev libxml2-dev libsqlite3-dev
sudo apt-get install  libiksemel-dev libssl-dev libasound2-dev
libcurl4-gnutls-dev libsrtp0-dev doxygen
git clone http://github.com/asterisk/pjproject pjproject
cd pjproject/
./configure --prefix=/usr --enable-shared
make dep; make
sudo make install
cd ..
svn co http://svn.digium.com/svn/asterisk/trunk asterisk
cd asterisk/
./configure
make
sudo make install
sudo make samples
sudo make progdocs
cp contrib/init.d/rc.debian.asterisk /etc/init.d/asterisk (adapt paths
to asterisk etc)
cp etc_default_asterisk /etc/default/asterisk (no color, coredumps)
chmod +x /etc/init.d/asterisk
vi /etc/asterisk/modules.conf  (noload chan_sip.so)
vi /etc/asterisk/res_sip.conf (clear and fill with config as in previous post)
/etc/init.d/asterisk start
asterisk -r

configure Bria with SIP account: userid: 101, domain: ipaddress
asterisk, password: 101

Dial 1000: Call failed to connect

I hope you have some suggestions, because I'm out of ideas.

Thanks,
Ron

PS: complete /var/log/asterisk/messages:

[Jun 20 22:07:01] Asterisk SVN-trunk-r392335 built by raarts @
parallels-Parallels-Virtual-Platform on a x86_64 running Linux on
2013-06-20 19:5
1:16 UTC
[Jun 20 22:07:01] WARNING[18853] config_options.c: Cannot update type
'globals' in module 'features' because it has no existing
documentation!
[Jun 20 22:07:01] WARNING[18853] config_options.c: Cannot update type
'featuremap' in module 'features' because it has no existing
documentation
!
[Jun 20 22:07:01] WARNING[18853] config_options.c: Cannot update type
'applicationmap' in module 'features' because it has no existing
documenta
tion!
[Jun 20 22:07:01] WARNING[18853] config_options.c: Cannot update type
'featuregroup' in module 'features' because it has no existing
documentati
on!
[Jun 20 22:07:01] ERROR[18853] config_options.c: XML Documentation for
option 'featuredigittimeout' in modules 'features' not found!
[Jun 20 22:07:01] ERROR[18853] config_options.c: XML Documentation for
option 'courtesytone' in modules 'features'
not found!

[.. snipped a lot of similar messages ..]

[Jun 20 22:07:01] ERROR[18853] config_options.c: XML Documentation for
option '^.*$' in modules 'features' not found!
[Jun 20 22:07:01] ERROR[18853] config_options.c: XML Documentation for
option '^.*$' in modules 'features' not found!
[Jun 20 22:07:01] WARNING[18853] features_config.c: The option
'parkext' is no longer configurable in features.conf.
[Jun 20 22:07:01] WARNING[18853] features_config.c: The option
'parkpos' is no longer configurable in features.conf.
[Jun 20 22:07:01] WARNING[18853] features_config.c: The option
'context' is no longer configurable in features.conf.
[Jun 20 22:07:01] NOTICE[18853] cdr.c: CDR simple logging enabled.
[Jun 20 22:07:01] NOTICE[18853] loader.c: 244 modules will be loaded.
[Jun 20 22:07:02] NOTICE[18853] res_smdi.c: No SMDI interfaces are
available to listen on, not starting SMDI listener.
[Jun 20 22:07:02] WARNING[18853] loader.c: Error loading module
'app_speech_utils.so': /usr/lib/asterisk/modules/app_speech_utils.so:
undefined symbol: ast_speech_get_setting
[Jun 20 22:07:02] WARNING[18853] loader.c: Module
'app_speech_utils.so' could not be loaded.
[Jun 20 22:07:02] NOTICE[18853] config.c: Registered Config Engine sqlite3
[Jun 20 22:07:02] NOTICE[18853] config.c: Registered Config Engine curl
[Jun 20 22:07:02] NOTICE[18853] res_config_ldap.c: No directory user
found, anonymous binding as default.
[Jun 20 22:07:02] ERROR[18853] res_config_ldap.c: No directory URL or
host found.
[Jun 20 22:07:02] ERROR[18853] res_config_ldap.c: Cannot load LDAP
RealTime driver.
[Jun 20 22:07:02] NOTICE[18853] chan_skinny.c: Configuring skinny from
skinny.conf
[Jun 20 22:07:04] NOTICE[18853] confbridge/conf_config_parser.c:
Adding default_user profile to app_confbridge
[Jun 20 22:07:04] NOTICE[18853] pbx_ael.c: Starting AEL load process.
[Jun 20 22:07:04] NOTICE[18853] pbx_ael.c: AEL load process: parsed
config file name '/etc/asterisk/extensions.ael'.
[Jun 20 22:07:04] NOTICE[18853] pbx_ael.c: AEL load process: checked
config file name '/etc/asterisk/extensions.ael'.
[Jun 20 22:07:04] NOTICE[18853] pbx_ael.c: AEL load process: compiled
config file name '/etc/asterisk/extensions.ael'.
[Jun 20 22:07:04] NOTICE[18853] pbx_ael.c: AEL load process: merged
config file name '/etc/asterisk/extensions.ael'.
[Jun 20 22:07:04] NOTICE[18853] pbx_ael.c: AEL load process: verified
config file name '/etc/asterisk/extensions.ael'.

complete console log with debugg+verbose added and set to level 8:

<--- Received SIP request (904 bytes) from UDP:10.211.55.2:8968 --->
INVITE sip:1000 at 10.211.55.90;transport=udp SIP/2.0
Via: SIP/2.0/UDP
10.211.55.2:8968;branch=z9hG4bK-d8754z-d858fa304e516852-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:101 at 10.211.55.2:8968;transport=udp>
To: <sip:1000 at 10.211.55.90>
From: <sip:101 at 10.211.55.90>;tag=dbd10a09
Call-ID: YmEyMmQwNTcyNDA4NDI1Yjk5NzNjZjM4NTI0MzAwN2M
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE,
SUBSCRIBE, INFO
Content-Type: application/sdp
Supported: replaces
User-Agent: Bria 3 release 3.5.2 stamp 70365
Content-Length: 345

v=0
o=- 1371759775852887 1 IN IP4 10.211.55.2
s=Bria 3 release 3.5.2 stamp 70365
c=IN IP4 10.211.55.2
t=0 0
m=audio 62750 RTP/AVP 122 120 9 8 0 18 101
a=rtpmap:122 opus/48000/2
a=fmtp:122 useinbandfec=1
a=rtpmap:120 SILK/16000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv

[Jun 20 22:22:55] DEBUG[19430]: res_sip_endpoint_identifier_user.c:104
username_identify: Retrieved endpoint 101
<--- Transmitting SIP response (498 bytes) to UDP:10.211.55.2:8968 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP
10.211.55.2:8968;rport;received=10.211.55.2;branch=z9hG4bK-d8754z-d858fa304e516852-1---d8754z-
Call-ID: YmEyMmQwNTcyNDA4NDI1Yjk5NzNjZjM4NTI0MzAwN2M
From: <sip:101 at 10.211.55.90>;tag=dbd10a09
To: <sip:1000 at 10.211.55.90>;tag=z9hG4bK-d8754z-d858fa304e516852-1---d8754z-
CSeq: 1 INVITE
WWW-Authenticate: Digest
realm="asterisk",nonce="1371759775/666d8f75e7e63c15aa836e19152fb747",opaque="472c689c25c1eef2",algorithm=md5,qop="auth"
Content-Length:  0

<--- Received SIP request (367 bytes) from UDP:10.211.55.2:8968 --->
ACK sip:1000 at 10.211.55.90;transport=udp SIP/2.0
Via: SIP/2.0/UDP
10.211.55.2:8968;branch=z9hG4bK-d8754z-d858fa304e516852-1---d8754z-;rport
Max-Forwards: 70
To: <sip:1000 at 10.211.55.90>;tag=z9hG4bK-d8754z-d858fa304e516852-1---d8754z-
From: <sip:101 at 10.211.55.90>;tag=dbd10a09
Call-ID: YmEyMmQwNTcyNDA4NDI1Yjk5NzNjZjM4NTI0MzAwN2M
CSeq: 1 ACK
Content-Length: 0

[Jun 20 22:22:55] DEBUG[19430]: res_sip_endpoint_identifier_user.c:104
username_identify: Retrieved endpoint 101
<--- Received SIP request (1200 bytes) from UDP:10.211.55.2:8968 --->
INVITE sip:1000 at 10.211.55.90;transport=udp SIP/2.0
Via: SIP/2.0/UDP
10.211.55.2:8968;branch=z9hG4bK-d8754z-5a1f3e3c71c82705-1---d8754z-;rport
Max-Forwards: 70
Contact: <sip:101 at 10.211.55.2:8968;transport=udp>
To: <sip:1000 at 10.211.55.90>
From: <sip:101 at 10.211.55.90>;tag=dbd10a09
Call-ID: YmEyMmQwNTcyNDA4NDI1Yjk5NzNjZjM4NTI0MzAwN2M
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE,
SUBSCRIBE, INFO
Content-Type: application/sdp
Supported: replaces
User-Agent: Bria 3 release 3.5.2 stamp 70365
Authorization: Digest
username="101",realm="asterisk",nonce="1371759775/666d8f75e7e63c15aa836e19152fb747",uri="sip:1000 at 10.211.55.90;transport=udp",response="654e05e6f456329b438c4606dee74259",cnonce="b904c42a35a7e90e43f7c93822d21435",nc=00000001,qop=auth,algorithm=md5,opaque="472c689c25c1eef2"
Content-Length: 345

v=0
o=- 1371759775852887 1 IN IP4 10.211.55.2
s=Bria 3 release 3.5.2 stamp 70365
c=IN IP4 10.211.55.2
t=0 0
m=audio 62750 RTP/AVP 122 120 9 8 0 18 101
a=rtpmap:122 opus/48000/2
a=fmtp:122 useinbandfec=1
a=rtpmap:120 SILK/16000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv

[Jun 20 22:22:55] DEBUG[19430]: res_sip_endpoint_identifier_user.c:104
username_identify: Retrieved endpoint 101
[Jun 20 22:22:55] DEBUG[19430]: res_sip_authenticator_digest.c:244
check_nonce: Calculated nonce
1371759775/666d8f75e7e63c15aa836e19152fb747. Actual nonce is
1371759775/666d8f75e7e63c15aa836e19152fb747
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1438
handle_outgoing_response: Response is 404 Not Found
<--- Transmitting SIP response (337 bytes) to UDP:10.211.55.2:8968 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP
10.211.55.2:8968;rport;received=10.211.55.2;branch=z9hG4bK-d8754z-5a1f3e3c71c82705-1---d8754z-
Call-ID: YmEyMmQwNTcyNDA4NDI1Yjk5NzNjZjM4NTI0MzAwN2M
From: <sip:101 at 10.211.55.90>;tag=dbd10a09
To: <sip:1000 at 10.211.55.90>;tag=M-hVnYqdb3FhsjuT9yOw34Oe2ql.OdVD
CSeq: 2 INVITE
Content-Length:  0

[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1345
__print_debug_details: Function session_inv_on_state_changed called on
event TSX_STATE
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1356
__print_debug_details: The state change pertains to the session with
101
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1359
__print_debug_details: The inv session still has an invite_tsx
(0x7fbd78004228)
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1368
__print_debug_details: There is no transaction involved in this state
change
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1370
__print_debug_details: The current inv state is DISCONNCTD
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1494
session_inv_on_state_changed: Source of transaction state change is
TX_MSG
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1454
handle_outgoing: Sending response
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1438
handle_outgoing_response: Response is 404 Not Found
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:871
session_destructor: Destroying SIP session with endpoint 101
[Jun 20 22:22:55] DEBUG[19430]: taskprocessor.c:426
tps_taskprocessor_destroy: destroying taskprocessor
'1500eb68-40e1-440e-a5bc-4948c35dbce6'
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1345
__print_debug_details: Function session_inv_on_tsx_state_changed
called on event TSX_STATE
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1353
__print_debug_details: inv_session 0x7fbd94007e48 has no ast session
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1359
__print_debug_details: The inv session still has an invite_tsx
(0x7fbd78004228)
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1364
__print_debug_details: The transaction involved in this state change
is 0x7fbd78004228
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1365
__print_debug_details: The current transaction state is Completed
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1366
__print_debug_details: The transaction state change event is TX_MSG
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1370
__print_debug_details: The current inv state is DISCONNCTD
<--- Received SIP request (356 bytes) from UDP:10.211.55.2:8968 --->
ACK sip:1000 at 10.211.55.90;transport=udp SIP/2.0
Via: SIP/2.0/UDP
10.211.55.2:8968;branch=z9hG4bK-d8754z-5a1f3e3c71c82705-1---d8754z-;rport
Max-Forwards: 70
To: <sip:1000 at 10.211.55.90>;tag=M-hVnYqdb3FhsjuT9yOw34Oe2ql.OdVD
From: <sip:101 at 10.211.55.90>;tag=dbd10a09
Call-ID: YmEyMmQwNTcyNDA4NDI1Yjk5NzNjZjM4NTI0MzAwN2M
CSeq: 2 ACK
Content-Length: 0

[Jun 20 22:22:55] DEBUG[19430]: res_sip_endpoint_identifier_user.c:104
username_identify: Retrieved endpoint 101
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1345
__print_debug_details: Function session_inv_on_tsx_state_changed
called on event TSX_STATE
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1353
__print_debug_details: inv_session 0x7fbd94007e48 has no ast session
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1359
__print_debug_details: The inv session still has an invite_tsx
(0x7fbd78004228)
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1364
__print_debug_details: The transaction involved in this state change
is 0x7fbd78004228
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1365
__print_debug_details: The current transaction state is Confirmed
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1366
__print_debug_details: The transaction state change event is RX_MSG
[Jun 20 22:22:55] DEBUG[19430]: res_sip_session.c:1370
__print_debug_details: The current inv state is DISCONNCTD
[Jun 20 22:22:55] DEBUG[18870]: res_sip_session.c:1345
__print_debug_details: Function session_inv_on_tsx_state_changed
called on event TSX_STATE
[Jun 20 22:22:55] DEBUG[18870]: res_sip_session.c:1353
__print_debug_details: inv_session 0x7fbd94007e48 has no ast session
[Jun 20 22:22:55] DEBUG[18870]: res_sip_session.c:1361
__print_debug_details: The inv session does NOT have an invite_tsx
[Jun 20 22:22:55] DEBUG[18870]: res_sip_session.c:1364
__print_debug_details: The transaction involved in this state change
is 0x7fbd78004228
[Jun 20 22:22:55] DEBUG[18870]: res_sip_session.c:1365
__print_debug_details: The current transaction state is Terminated
[Jun 20 22:22:55] DEBUG[18870]: res_sip_session.c:1366
__print_debug_details: The transaction state change event is TIMER
[Jun 20 22:22:55] DEBUG[18870]: res_sip_session.c:1370
__print_debug_details: The current inv state is DISCONNCTD
[Jun 20 22:23:17] DEBUG[19434]: threadpool.c:1104 worker_idle: Worker
thread idle timeout reached. Dying.
[Jun 20 22:23:17] DEBUG[19433]: threadpool.c:1104 worker_idle: Worker
thread idle timeout reached. Dying.
[Jun 20 22:23:17] DEBUG[19432]: threadpool.c:1104 worker_idle: Worker
thread idle timeout reached. Dying.
[Jun 20 22:23:17] DEBUG[19431]: threadpool.c:1104 worker_idle: Worker
thread idle timeout reached. Dying.
[Jun 20 22:23:17] DEBUG[18869]: threadpool.c:965
worker_thread_destroy: Destroying worker thread 15
[Jun 20 22:23:17] DEBUG[18869]: threadpool.c:965
worker_thread_destroy: Destroying worker thread 14
[Jun 20 22:23:17] DEBUG[18869]: threadpool.c:965
worker_thread_destroy: Destroying worker thread 13
[Jun 20 22:23:17] DEBUG[18869]: threadpool.c:965
worker_thread_destroy: Destroying worker thread 12