[asterisk-dev] Start testing with res_sip
Mark Michelson
mmichelson at digium.com
Thu Jun 20 11:18:54 CDT 2013
On 06/20/2013 10:10 AM, Ron Arts wrote:
> On Thu, Jun 20, 2013 at 4:29 PM, Mark Michelson <mmichelson at digium.com> wrote:
>> On 06/20/2013 01:43 AM, Ron Arts wrote:
>>> Hi,
>>>
>>> I cannot get authentication to work with res_sip. I get a not found.
>>> Is there a way to enable
>>> debugging in res_sip? The SIP trace below appears automatically, and I
>>> don't know how to
>>> stop that, but OTOH chan_sip has debugging that shows where it's
>>> looking for and why it can't
>>> find the peer. I include my res_sip.conf below. It's very short.
>>>
>>> Thanks,
>>> Ron
>>>
>> A way that you can stop the SIP trace from appearing is to "module unload
>> res_sip_logger.so" from the CLI. Or you can noload res_sip_logger.so from
>> modules.conf and just load it when you need to start seeing SIP traces. The
>> best you're going to find for debugging right now is the core debugging
>> feature. Just ensure that the console is receiving debug messages in
>> logger.conf, and then set your debug log level to 3 or higher ("core set
>> debug 3") and you'll probably see everything that's being logged at the
>> moment. If you have specific ideas for improvements for log messages, feel
>> free to let us know (or even contribute them).
>>
>> Regarding the problem you're seeing, I'm not sure why you'd be seeing it. It
>> looks like you adapted the configuration from the issue that Malcolm linked
>> to, and I know authentication was working for him when he was testing. My
>> guess is that there is a module that either failed to load or just is not
>> configured to load that needs to be there. If you run a "module show like
>> res_sip" command in your CLI what all shows up?
>>
>> Mark Michelson
>>
>>
> With 'core set verbose 8' I get the following:
>
[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).
*CLI> <--- Received SIP request (1057 bytes) from UDP:10.24.19.174:5060 --->
INVITE sip:1000 at 10.24.20.249 SIP/2.0
Via: SIP/2.0/UDP
10.24.19.174:5060;rport;branch=z9hG4bKPjN9ufgjKlrN6WcwXq3g3LZaTRuk4wOHO8
Max-Forwards: 70
From: "101" <sip:101 at 10.24.20.249>;tag=NLam4DjStke5mmrIpeqccwh4eROTlWfJ
To: sip:1000 at 10.24.20.249
Contact: "101" <sip:101 at 10.24.19.174:5060;ob>
Call-ID: eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh
CSeq: 21295 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY,
REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
User-Agent: Digium D40 1_0_5_1_47270
Content-Type: application/sdp
Content-Length: 431
v=0
o=- 67116157 67116157 IN IP4 10.24.19.174
s=digphn
c=IN IP4 10.24.19.174
t=0 0
a=X-nat:0
m=audio 4002 RTP/AVP 0 8 9 111 18 58 118 58 96
a=rtcp:4003 IN IP4 10.24.19.174
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:18 G729/8000
a=rtpmap:58 L16/16000
a=rtpmap:118 L16/8000
a=rtpmap:58 L16-256/16000
a=sendrecv
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15
<--- Transmitting SIP response (519 bytes) to UDP:10.24.19.174:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP
10.24.19.174:5060;rport;received=10.24.19.174;branch=z9hG4bKPjN9ufgjKlrN6WcwXq3g3LZaTRuk4wOHO8
Call-ID: eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh
From: "101" <sip:101 at 10.24.20.249>;tag=NLam4DjStke5mmrIpeqccwh4eROTlWfJ
To: <sip:1000 at 10.24.20.249>;tag=z9hG4bKPjN9ufgjKlrN6WcwXq3g3LZaTRuk4wOHO8
CSeq: 21295 INVITE
WWW-Authenticate: Digest
realm="asterisk",nonce="1371743714/9c347fc5eff16d0c5f463f685626df2a",opaque="2c487e6b4ddeeb7b",algorithm=md5,qop="auth"
Content-Length: 0
<--- Received SIP request (372 bytes) from UDP:10.24.19.174:5060 --->
ACK sip:1000 at 10.24.20.249 SIP/2.0
Via: SIP/2.0/UDP
10.24.19.174:5060;rport;branch=z9hG4bKPjN9ufgjKlrN6WcwXq3g3LZaTRuk4wOHO8
Max-Forwards: 70
From: "101" <sip:101 at 10.24.20.249>;tag=NLam4DjStke5mmrIpeqccwh4eROTlWfJ
To: sip:1000 at 10.24.20.249;tag=z9hG4bKPjN9ufgjKlrN6WcwXq3g3LZaTRuk4wOHO8
Call-ID: eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh
CSeq: 21295 ACK
Content-Length: 0
<--- Received SIP request (1348 bytes) from UDP:10.24.19.174:5060 --->
INVITE sip:1000 at 10.24.20.249 SIP/2.0
Via: SIP/2.0/UDP
10.24.19.174:5060;rport;branch=z9hG4bKPjqS2NAxw3OQ.qXNiPJNkV7Mf8pXn2S0Vk
Max-Forwards: 70
From: "101" <sip:101 at 10.24.20.249>;tag=NLam4DjStke5mmrIpeqccwh4eROTlWfJ
To: sip:1000 at 10.24.20.249
Contact: "101" <sip:101 at 10.24.19.174:5060;ob>
Call-ID: eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh
CSeq: 21296 INVITE
Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, SUBSCRIBE, NOTIFY,
REFER, MESSAGE, OPTIONS
Supported: replaces, 100rel, timer, norefersub
Session-Expires: 1800
Min-SE: 90
User-Agent: Digium D40 1_0_5_1_47270
Authorization: Digest username="101", realm="asterisk",
nonce="1371743714/9c347fc5eff16d0c5f463f685626df2a",
uri="sip:1000 at 10.24.20.249",
response="bc3e9ef55f7c1994d68d2a3dfba10b5e", algorithm=md5,
cnonce="gVp1iVUEhZ8o3v.5Y7XQyDSKpFaO.HFI", opaque="2c487e6b4ddeeb7b",
qop=auth, nc=00000001
Content-Type: application/sdp
Content-Length: 431
v=0
o=- 67116157 67116157 IN IP4 10.24.19.174
s=digphn
c=IN IP4 10.24.19.174
t=0 0
a=X-nat:0
m=audio 4002 RTP/AVP 0 8 9 111 18 58 118 58 96
a=rtcp:4003 IN IP4 10.24.19.174
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:18 G729/8000
a=rtpmap:58 L16/16000
a=rtpmap:118 L16/8000
a=rtpmap:58 L16-256/16000
a=sendrecv
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15
<--- Transmitting SIP response (320 bytes) to UDP:10.24.19.174:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP
10.24.19.174:5060;rport;received=10.24.19.174;branch=z9hG4bKPjqS2NAxw3OQ.qXNiPJNkV7Mf8pXn2S0Vk
Call-ID: eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh
From: "101" <sip:101 at 10.24.20.249>;tag=NLam4DjStke5mmrIpeqccwh4eROTlWfJ
To: <sip:1000 at 10.24.20.249>
CSeq: 21296 INVITE
Content-Length: 0
-- Executing [1000 at testing:1]
NoOp("Gulp/101-eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh", "THIS WORKS!") in new
stack
-- Executing [1000 at testing:2]
Answer("Gulp/101-eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh", "") in new stack
<--- Transmitting SIP response (774 bytes) to UDP:10.24.19.174:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP
10.24.19.174:5060;rport;received=10.24.19.174;branch=z9hG4bKPjqS2NAxw3OQ.qXNiPJNkV7Mf8pXn2S0Vk
Call-ID: eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh
From: "101" <sip:101 at 10.24.20.249>;tag=NLam4DjStke5mmrIpeqccwh4eROTlWfJ
To: <sip:1000 at 10.24.20.249>;tag=0234c5c7-6ea9-4030-b823-418a12dfb145
CSeq: 21296 INVITE
Contact: <sip:1000 at 10.24.20.249>
Allow: OPTIONS, SUBSCRIBE, NOTIFY, INVITE, ACK, BYE, CANCEL, UPDATE,
PRACK, REGISTER
Supported: 100rel, timer
Content-Type: application/sdp
Content-Length: 237
v=0
o=Asterisk 67116157 67116159 IN IP4 levin
s=Asterisk
c=IN IP4 10.24.20.249
t=0 0
m=audio 12798 RTP/AVP 9 96
c=IN IP4 10.24.20.249
a=rtpmap:9 G722/8000
a=ptime:20
a=sendrecv
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
<--- Received SIP request (367 bytes) from UDP:10.24.19.174:5060 --->
ACK sip:1000 at 10.24.20.249 SIP/2.0
Via: SIP/2.0/UDP
10.24.19.174:5060;rport;branch=z9hG4bKPjzZpda8UdsEIy4SEOVXOw9aGEPx6Ybg7G
Max-Forwards: 70
From: "101" <sip:101 at 10.24.20.249>;tag=NLam4DjStke5mmrIpeqccwh4eROTlWfJ
To: sip:1000 at 10.24.20.249;tag=0234c5c7-6ea9-4030-b823-418a12dfb145
Call-ID: eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh
CSeq: 21296 ACK
Content-Length: 0
> 0xa7369b8 -- Probation passed - setting RTP source address to
10.24.19.174:4002
-- Executing [1000 at testing:3]
Playback("Gulp/101-eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh", "hello-world") in
new stack
-- <Gulp/101-eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh> Playing
'hello-world.gsm' (language 'en')
-- Executing [1000 at testing:4]
Hangup("Gulp/101-eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh", "") in new stack
== Spawn extension (testing, 1000, 4) exited non-zero on
'Gulp/101-eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh'
<--- Transmitting SIP request (403 bytes) to UDP:10.24.19.174:5060 --->
BYE sip:101 at 10.24.19.174:5060;ob SIP/2.0
Via: SIP/2.0/UDP
10.24.20.249:5060;rport;branch=z9hG4bKPjbda9abc6-2afd-4398-8891-c4083615d024
Max-Forwards: 70
From: <sip:1000 at 10.24.20.249>;tag=0234c5c7-6ea9-4030-b823-418a12dfb145
To: "101" <sip:101 at 10.24.20.249>;tag=NLam4DjStke5mmrIpeqccwh4eROTlWfJ
Call-ID: eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh
CSeq: 8746 BYE
Reason: Q.850;cause=16
Content-Length: 0
<--- Received SIP response (362 bytes) from UDP:10.24.19.174:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP
10.24.20.249:5060;rport=5060;received=10.24.20.249;branch=z9hG4bKPjbda9abc6-2afd-4398-8891-c4083615d024
Call-ID: eIGPoGBlf43ci7ZT0hyD8TQGQTvoIwYh
From: <sip:1000 at 10.24.20.249>;tag=0234c5c7-6ea9-4030-b823-418a12dfb145
To: "101" <sip:101 at 10.24.20.249>;tag=NLam4DjStke5mmrIpeqccwh4eROTlWfJ
CSeq: 8746 BYE
Content-Length: 0
More information about the asterisk-dev
mailing list