Home » Forums » Community Edition » Help

Problem after yum update / SIP/2.0 404 Not Found

hipan
Posts: 4
 Member Since:
2008-12-20
Submitted by hipan on Sat, 12/20/2008 - 10:58am.

Hello everyone.

I've just updated my system (yum update) and after rebooting, asterisk is (mostly) broken. Incoming calls seem to work, and "sip show registry" shows that I am Registered. Trixbox is v2.6.1.10

The problem is with making calls, or attempting to call outbound.

When an extension (5005) calls another extension (5003), the calling user gets a busy signal. In the logs, I have found "SIP/2.0 404 Not Found". Here is the full output from atemping to call extension 5003, from 5005:

<--- SIP read from 192.168.9.17:5064 --->
INVITE sip:5003@192.168.2.10 SIP/2.0
Date: Sat, 20 Dec 2008 18:34:49 GMT
CSeq: 1 INVITE
Via: SIP/2.0/UDP 192.168.9.17:5064;branch=z9hG4bK00877f8d-32cd-dd11-93b2-000ea61e65c5;rport
User-Agent: Ekiga/2.0.12
From: "Kyle Johnson" <sip:5005@192.168.2.10>;tag=8e9f658d-32cd-dd11-93b2-000ea61e65c5
Call-ID: 9697658d-32cd-dd11-93b2-000ea61e65c5@kjohnson-desktop
To: <sip:5003@192.168.2.10>
Contact: <sip:5005@192.168.9.17:5061;transport=udp>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE
Content-Type: application/sdp
Content-Length: 387
Max-Forwards: 70

v=0
o=- 1229798089 1229798089 IN IP4 192.168.9.17
s=Opal SIP Session
c=IN IP4 192.168.9.17
t=0 0
m=audio 5004 RTP/AVP 96 3 107 110 0 8 101
a=rtpmap:96 SPEEX/16000
a=rtpmap:3 GSM/8000
a=rtpmap:107 MS-GSM/8000
a=rtpmap:110 SPEEX/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
m=video 5006 RTP/AVP 31
a=rtpmap:31 H261/90000

<------------->
[Dec 20 13:34:25] VERBOSE[3287] logger.c: --- (13 headers 16 lines) ---
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Sending to 192.168.9.17 : 5064 (NAT)
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Using INVITE request as basis request - 9697658d-32cd-dd11-93b2-000ea61e65c5@kjohnson-desktop
[Dec 20 13:34:25] VERBOSE[3287] logger.c: 
<--- Reliably Transmitting (NAT) to 192.168.9.17:5064 --->
SIP/2.0 407 Proxy Authentication Required
Via: SIP/2.0/UDP 192.168.9.17:5064;branch=z9hG4bK00877f8d-32cd-dd11-93b2-000ea61e65c5;received=192.168.9.17;rport=5064
From: "Kyle Johnson" <sip:5005@192.168.2.10>;tag=8e9f658d-32cd-dd11-93b2-000ea61e65c5
To: <sip:5003@192.168.2.10>;tag=as702c5dce
Call-ID: 9697658d-32cd-dd11-93b2-000ea61e65c5@kjohnson-desktop
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="002158ec"
Content-Length: 0


<------------>
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Scheduling destruction of SIP dialog '9697658d-32cd-dd11-93b2-000ea61e65c5@kjohnson-desktop' in 32000 ms (Method: INVITE)
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found user '5005'
[Dec 20 13:34:25] VERBOSE[3287] logger.c: 
<--- SIP read from 192.168.9.17:5064 --->
ACK sip:5003@192.168.2.10 SIP/2.0
CSeq: 1 ACK
Via: SIP/2.0/UDP 192.168.9.17:5064;branch=z9hG4bK00877f8d-32cd-dd11-93b2-000ea61e65c5;rport
From: "Kyle Johnson" <sip:5005@192.168.2.10>;tag=8e9f658d-32cd-dd11-93b2-000ea61e65c5
Call-ID: 9697658d-32cd-dd11-93b2-000ea61e65c5@kjohnson-desktop
To: <sip:5003@192.168.2.10>;tag=as702c5dce
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE
Content-Length: 0
Max-Forwards: 70


<------------->
[Dec 20 13:34:25] VERBOSE[3287] logger.c: --- (9 headers 0 lines) ---
[Dec 20 13:34:25] VERBOSE[3287] logger.c: 
<--- SIP read from 192.168.9.17:5064 --->
INVITE sip:5003@192.168.2.10 SIP/2.0
Date: Sat, 20 Dec 2008 18:34:49 GMT
CSeq: 2 INVITE
Via: SIP/2.0/UDP 192.168.9.17:5064;branch=z9hG4bK983e8a8d-32cd-dd11-93b2-000ea61e65c5;rport
User-Agent: Ekiga/2.0.12
From: "Kyle Johnson" <sip:5005@192.168.2.10>;tag=8e9f658d-32cd-dd11-93b2-000ea61e65c5
Call-ID: 9697658d-32cd-dd11-93b2-000ea61e65c5@kjohnson-desktop
To: <sip:5003@192.168.2.10>
Contact: <sip:5005@192.168.9.17:5061;transport=udp>
Proxy-Authorization: Digest username="5005", realm="asterisk", nonce="002158ec", uri="sip:5003@192.168.2.10", algorithm=md5, response="094a643070aaea07e1d4dc8d3154a9ac"
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE
Content-Type: application/sdp
Content-Length: 387
Max-Forwards: 70

v=0
o=- 1229798089 1229798089 IN IP4 192.168.9.17
s=Opal SIP Session
c=IN IP4 192.168.9.17
t=0 0
m=audio 5004 RTP/AVP 96 3 107 110 0 8 101
a=rtpmap:96 SPEEX/16000
a=rtpmap:3 GSM/8000
a=rtpmap:107 MS-GSM/8000
a=rtpmap:110 SPEEX/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
m=video 5006 RTP/AVP 31
a=rtpmap:31 H261/90000

<------------->
[Dec 20 13:34:25] VERBOSE[3287] logger.c: --- (14 headers 16 lines) ---
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Sending to 192.168.9.17 : 5064 (NAT)
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Using INVITE request as basis request - 9697658d-32cd-dd11-93b2-000ea61e65c5@kjohnson-desktop
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found user '5005'
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found RTP audio format 96
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found RTP audio format 3
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found RTP audio format 107
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found RTP audio format 110
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found RTP audio format 0
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found RTP audio format 8
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found RTP audio format 101
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found RTP video format 31
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Peer audio RTP is at port 192.168.9.17:5004
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found audio description format SPEEX for ID 96
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found audio description format GSM for ID 3
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found unknown media description format MS-GSM for ID 107
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found audio description format SPEEX for ID 110
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found audio description format PCMU for ID 0
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found audio description format PCMA for ID 8
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found audio description format telephone-event for ID 101
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Found unknown media description format H261 for ID 31
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x20e (gsm|ulaw|alaw|speex)/video=0x0 (nothing), combined - 0xc (ulaw|alaw)
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Peer audio RTP is at port 192.168.9.17:5004
[Dec 20 13:34:25] DEBUG[3287] chan_sip.c: Call from peer '5005' is 1 out of 50
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Looking for 5003 in from-internal (domain 192.168.2.10)
[Dec 20 13:34:25] VERBOSE[3287] logger.c: 
<--- Reliably Transmitting (NAT) to 192.168.9.17:5064 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 192.168.9.17:5064;branch=z9hG4bK983e8a8d-32cd-dd11-93b2-000ea61e65c5;received=192.168.9.17;rport=5064
From: "Kyle Johnson" <sip:5005@192.168.2.10>;tag=8e9f658d-32cd-dd11-93b2-000ea61e65c5
To: <sip:5003@192.168.2.10>;tag=as702c5dce
Call-ID: 9697658d-32cd-dd11-93b2-000ea61e65c5@kjohnson-desktop
CSeq: 2 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


<------------>
[Dec 20 13:34:25] NOTICE[3287] chan_sip.c: Call from '5005' to extension '5003' rejected because extension not found.
[Dec 20 13:34:25] DEBUG[3287] chan_sip.c: Call from peer '5005' removed from call limit 50
[Dec 20 13:34:25] VERBOSE[3287] logger.c: Scheduling destruction of SIP dialog '9697658d-32cd-dd11-93b2-000ea61e65c5@kjohnson-desktop' in 32000 ms (Method: INVITE)
[Dec 20 13:34:25] VERBOSE[3287] logger.c: 
<--- SIP read from 192.168.9.17:5064 --->
ACK sip:5003@192.168.2.10 SIP/2.0
CSeq: 2 ACK
Via: SIP/2.0/UDP 192.168.9.17:5064;branch=z9hG4bK983e8a8d-32cd-dd11-93b2-000ea61e65c5;rport
From: "Kyle Johnson" <sip:5005@192.168.2.10>;tag=8e9f658d-32cd-dd11-93b2-000ea61e65c5
Call-ID: 9697658d-32cd-dd11-93b2-000ea61e65c5@kjohnson-desktop
To: <sip:5003@192.168.2.10>;tag=as702c5dce
Proxy-Authorization: Digest username="5005", realm="asterisk", nonce="002158ec", uri="sip:5003@192.168.2.10", algorithm=md5, response="6bd1a4d111fc88392dfd2e7c9b9b6e74"
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE
Content-Length: 0
Max-Forwards: 70
bash-3.2# /usr/sbin/asterisk -V
Asterisk 1.4.21.2-2 RPM by <a href="mailto:vc-rpms@voipconsulting.nl">vc-rpms@voipconsulting.nl</a>

Any help is appreciated, and let me know what other information you may need.

Thank you!

‹ Can not press number prompts on outgoing IVRs Cisco Transferring + Blind Transfer + Conference ›

&nbsp

SkykingOH
Posts: 9677
 Member Since:
2007-12-17
Quote: [Dec 20 13:34:25]
Sat, 12/20/2008 - 1:20pm
Quote:
[Dec 20 13:34:25] NOTICE[3287] chan_sip.c: Call from '5005' to extension '5003' rejected because extension not found.

This line is your entire problem. what is the output of 'sip show peers' and 'sip show peer 5003' ???

Thanks for using the code tags and providing useful information, maybe others will notice your example.

--

Scott

aka "Skyking"


&nbsp

hipan
Posts: 4
 Member Since:
2008-12-20
Skyking, thanks for the
Sat, 12/20/2008 - 1:30pm

Skyking, thanks for the reply!
I always use code tags - they are there for a reason!

trixbox1*CLI> sip show peers
Name/username              Host            Dyn Nat ACL Port     Status               
Vitelity-Outbound/ronswif  64.2.142.87          N      5060     OK (74 ms)           
Vitelity-Inbound/ronswift  64.2.142.26          N      5060     OK (66 ms)           
5106/5106                  68.49.172.226    D   N      5060     OK (47 ms)           
5105/5105                  66.160.111.106   D   N      5060     OK (93 ms)           
5104/5104                  70.22.12.174     D   N      50577    OK (105 ms)           
5103/5103                  66.160.111.106   D   N      61336    OK (127 ms)           
5008                       (Unspecified)    D   N      0        UNKNOWN              
5007/5007                  192.168.2.194    D   N      5060     OK (54 ms)           
5006/5006                  192.168.2.198    D   N      5060     OK (13 ms)           
5005/5005                  192.168.9.17     D   N      5061     OK (45 ms)           
5004/5004                  192.168.2.199    D   N      5060     OK (78 ms)           
5003/5003                  192.168.2.196    D   N      5060     OK (18 ms)           
5001/5001                  (Unspecified)    D   N      0        UNKNOWN              
13 sip peers [Monitored: 11 online, 2 offline Unmonitored: 0 online, 0 offline]

trixbox1*CLI> sip show peer 5003

  * Name       : 5003
  Secret       : <Set>
  MD5Secret    : <Not set>
  Context      : from-internal
  Subscr.Cont. : <Not set>
  Language     : 
  AMA flags    : Unknown
  Transfer mode: open
  CallingPres  : Presentation Allowed, Not Screened
  Callgroup    : 
  Pickupgroup  : 
  Mailbox      : 5003@default
  VM Extension : *97
  LastMsgsSent : 0/34
  Call limit   : 50
  Dynamic      : Yes
  Callerid     : "device" <5003>
  MaxCallBR    : 384 kbps
  Expire       : 275
  Insecure     : no
  Nat          : Always
  ACL          : No
  T38 pt UDPTL : No
  CanReinvite  : No
  PromiscRedir : No
  User=Phone   : No
  Video Support: No
  Trust RPID   : No
  Send RPID    : No
  Subscriptions: Yes
  Overlap dial : Yes
  DTMFmode     : rfc2833
  LastMsg      : 0
  ToHost       : 
  Addr->IP     : 192.168.2.196 Port 5060
  Defaddr->IP  : 0.0.0.0 Port 5060
  Def. Username: 5003
  SIP Options  : (none)
  Codecs       : 0xc (ulaw|alaw)
  Codec Order  : (ulaw:20,alaw:20)
  Auto-Framing:  No 
  Status       : OK (19 ms)
  Useragent    : Sipura/SPA941-4.1.8
  Reg. Contact : sip:5003@192.168.2.196:5060
trixbox1*CLI>

Things look OK there?


&nbsp

SkykingOH
Posts: 9677
 Member Since:
2007-12-17
Not that simple. things do
Sat, 12/20/2008 - 3:29pm

Not that simple. things do look OK. Let's try a few more things:

  1. Use FreePBX to 'touch' the extension, edit something trivial in extension 5003 and save it and then apply the config
  2. From the command prompt restart everything (amportal restart)
  3. Start the CLI and crank the debug (core set debug 20)
  4. Call 5003 from 5003
  5. Turn the debug off (core set debug off)
  6. Post the relevant output from /var/log/etc/full

Hopefully that will give us a clue.

--

Scott

aka "Skyking"


&nbsp

hipan
Posts: 4
 Member Since:
2008-12-20
I manually removed the
Sat, 12/20/2008 - 5:02pm

I manually removed the "secret" from [5003] in /etc/asterisk/sip_additional.conf (the webui isn't working so well either, but this seems more important).
Then did asterisk -r, reload, core set debug 20, placed the call, and here is the output:

bash-3.2# tail -f full
[Dec 20 19:00:21] DEBUG[3287] chan_sip.c: Header 10: Content-Length: 0 (17)
[Dec 20 19:00:21] DEBUG[3287] chan_sip.c: Header 11:  (0)
[Dec 20 19:00:21] VERBOSE[3287] logger.c: --- (11 headers 0 lines) ---
[Dec 20 19:00:21] DEBUG[3287] chan_sip.c: = Found Their Call ID: 23032de121a23cb66a078d101e43a7bc@70.90.89.45 Their Tag  Our tag: as7213a537
[Dec 20 19:00:21] DEBUG[3287] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #22272
[Dec 20 19:00:21] DEBUG[3287] chan_sip.c: Stopping retransmission on '23032de121a23cb66a078d101e43a7bc@70.90.89.45' of Request 102: Match Found
[Dec 20 19:00:21] VERBOSE[3287] logger.c: Really destroying SIP dialog '23032de121a23cb66a078d101e43a7bc@70.90.89.45' Method: OPTIONS
[Dec 20 19:00:31] DEBUG[3287] chan_sip.c: Auto destroying SIP dialog '40d26f9b8e9b6f4e@192.168.2.197'
[Dec 20 19:00:31] DEBUG[3287] chan_sip.c: Destroying SIP dialog 40d26f9b8e9b6f4e@192.168.2.197
[Dec 20 19:00:31] VERBOSE[3287] logger.c: Really destroying SIP dialog '40d26f9b8e9b6f4e@192.168.2.197' Method: REGISTER
[Dec 20 19:00:36] VERBOSE[3287] logger.c: 
<--- SIP read from 192.168.9.17:5073 --->
INVITE sip:5003@192.168.2.10 SIP/2.0
Date: Sun, 21 Dec 2008 00:01:01 GMT
CSeq: 1 INVITE
Via: SIP/2.0/UDP 192.168.9.17:5073;branch=z9hG4bK4295f21e-60cd-dd11-93b2-000ea61e65c5;rport
User-Agent: Ekiga/2.0.12
From: "Kyle Johnson" <sip:5003@192.168.2.10>;tag=48e1eb1e-60cd-dd11-93b2-000ea61e65c5
Call-ID: 50d9eb1e-60cd-dd11-93b2-000ea61e65c5@kjohnson-desktop
To: <sip:5003@192.168.2.10>
Contact: <sip:5003@192.168.9.17:5061;transport=udp>
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE
Content-Type: application/sdp
Content-Length: 387
Max-Forwards: 70

v=0
o=- 1229817661 1229817661 IN IP4 192.168.9.17
s=Opal SIP Session
c=IN IP4 192.168.9.17
t=0 0
m=audio 5028 RTP/AVP 96 3 107 110 0 8 101
a=rtpmap:96 SPEEX/16000
a=rtpmap:3 GSM/8000
a=rtpmap:107 MS-GSM/8000
a=rtpmap:110 SPEEX/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
m=video 5030 RTP/AVP 31
a=rtpmap:31 H261/90000

<------------->
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 0: INVITE sip:5003@192.168.2.10 SIP/2.0 (36)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 1: Date: Sun, 21 Dec 2008 00:01:01 GMT (35)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 2: CSeq: 1 INVITE (14)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 3: Via: SIP/2.0/UDP 192.168.9.17:5073;branch=z9hG4bK4295f21e-60cd-dd11-93b2-000ea61e65c5;rport (91)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 4: User-Agent: Ekiga/2.0.12 (24)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 5: From: "Kyle Johnson" <sip:5003@192.168.2.10>;tag=48e1eb1e-60cd-dd11-93b2-000ea61e65c5 (85)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 6: Call-ID: 50d9eb1e-60cd-dd11-93b2-000ea61e65c5@kjohnson-desktop (62)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 7: To: <sip:5003@192.168.2.10> (27)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 8: Contact: <sip:5003@192.168.9.17:5061;transport=udp> (51)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 9: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE (57)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 10: Content-Type: application/sdp (29)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 11: Content-Length: 387 (19)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 12: Max-Forwards: 70 (16)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 13:  (0)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: v=0 (3)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: o=- 1229817661 1229817661 IN IP4 192.168.9.17 (45)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: s=Opal SIP Session (18)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: c=IN IP4 192.168.9.17 (21)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: t=0 0 (5)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: m=audio 5028 RTP/AVP 96 3 107 110 0 8 101 (41)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: a=rtpmap:96 SPEEX/16000 (23)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: a=rtpmap:3 GSM/8000 (19)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: a=rtpmap:107 MS-GSM/8000 (24)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: a=rtpmap:110 SPEEX/8000 (23)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: a=fmtp:101 0-15 (15)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: m=video 5030 RTP/AVP 31 (23)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Line: a=rtpmap:31 H261/90000 (22)
[Dec 20 19:00:36] VERBOSE[3287] logger.c: --- (13 headers 16 lines) ---
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: = No match Their Call ID: 79316e1f09b1210650e871361fd25997@127.0.0.1 Their Tag as00c7dc23 Our tag: as3a4d332c
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: = No match Their Call ID: 4a9076ea-5dcd-dd11-93b2-000ea61e65c5@kjohnson-desktop Their Tag ce628e49-5ecd-dd11-93b2-000ea61e65c5 Our tag: as2fa2517b
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: = No match Their Call ID: b87af728-32cd-dd11-93b2-000ea61e65c5@kjohnson-desktop Their Tag 80b43e30-32cd-dd11-93b2-000ea61e65c5 Our tag: as72776ee0
[Dec 20 19:00:36] DEBUG[3287] acl.c: ##### Testing 192.168.9.17 with 192.168.2.0
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Target address 192.168.9.17 is not local, substituting externip
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Setting NAT on RTP to On
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Allocating new SIP dialog for 50d9eb1e-60cd-dd11-93b2-000ea61e65c5@kjohnson-desktop - INVITE (With RTP)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Sending to 192.168.9.17 : 5073 (NAT)
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Using INVITE request as basis request - 50d9eb1e-60cd-dd11-93b2-000ea61e65c5@kjohnson-desktop
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Setting NAT on RTP to On
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found user '5003'
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found RTP audio format 96
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found RTP audio format 3
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found RTP audio format 107
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found RTP audio format 110
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found RTP audio format 0
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found RTP audio format 8
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found RTP audio format 101
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found RTP video format 31
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Peer audio RTP is at port 192.168.9.17:5028
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found audio description format SPEEX for ID 96
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found audio description format GSM for ID 3
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found unknown media description format MS-GSM for ID 107
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found audio description format SPEEX for ID 110
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found audio description format PCMU for ID 0
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found audio description format PCMA for ID 8
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found audio description format telephone-event for ID 101
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Got unsupported a:fmtp in SDP offer 
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Found unknown media description format H261 for ID 31
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: T38 state changed to 0 on channel <none>
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Capabilities: us - 0xc (ulaw|alaw), peer - audio=0x20e (gsm|ulaw|alaw|speex)/video=0x0 (nothing), combined - 0xc (ulaw|alaw)
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event)
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Peer audio RTP is at port 192.168.9.17:5028
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: We're settling with these formats: 0xc (ulaw|alaw)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Checking SIP call limits for device 5003
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Updating call counter for incoming call
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Call from peer '5003' is 1 out of 50
[Dec 20 19:00:36] DEBUG[3287] devicestate.c: Notification of state change to be queued on device/channel SIP/5003
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Looking for 5003 in from-internal (domain 192.168.2.10)
[Dec 20 19:00:36] VERBOSE[3287] logger.c: 
<--- Reliably Transmitting (NAT) to 192.168.9.17:5073 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 192.168.9.17:5073;branch=z9hG4bK4295f21e-60cd-dd11-93b2-000ea61e65c5;received=192.168.9.17;rport=5073
From: "Kyle Johnson" <sip:5003@192.168.2.10>;tag=48e1eb1e-60cd-dd11-93b2-000ea61e65c5
To: <sip:5003@192.168.2.10>;tag=as6e99f216
Call-ID: 50d9eb1e-60cd-dd11-93b2-000ea61e65c5@kjohnson-desktop
CSeq: 1 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


<------------>
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #-1
[Dec 20 19:00:36] NOTICE[3287] chan_sip.c: Call from '5003' to extension '5003' rejected because extension not found.
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Updating call counter for incoming call
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Call from peer '5003' removed from call limit 50
[Dec 20 19:00:36] DEBUG[3287] devicestate.c: Notification of state change to be queued on device/channel SIP/5003
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Scheduling destruction of SIP dialog '50d9eb1e-60cd-dd11-93b2-000ea61e65c5@kjohnson-desktop' in 32000 ms (Method: INVITE)
[Dec 20 19:00:36] DEBUG[3266] devicestate.c: No provider found, checking channel drivers for SIP - 5003
[Dec 20 19:00:36] DEBUG[3266] chan_sip.c: Checking device state for peer 5003
[Dec 20 19:00:36] DEBUG[3266] devicestate.c: Changing state for SIP/5003 - state 1 (Not in use)
[Dec 20 19:00:36] DEBUG[3266] devicestate.c: No provider found, checking channel drivers for SIP - 5003
[Dec 20 19:00:36] DEBUG[3266] chan_sip.c: Checking device state for peer 5003
[Dec 20 19:00:36] DEBUG[3266] devicestate.c: Changing state for SIP/5003 - state 1 (Not in use)
[Dec 20 19:00:36] DEBUG[3269] app_queue.c: Device 'SIP/5003' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Dec 20 19:00:36] DEBUG[3269] app_queue.c: Device 'SIP/5003' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Dec 20 19:00:36] VERBOSE[3287] logger.c: 
<--- SIP read from 192.168.9.17:5073 --->
ACK sip:5003@192.168.2.10 SIP/2.0
CSeq: 1 ACK
Via: SIP/2.0/UDP 192.168.9.17:5073;branch=z9hG4bK4295f21e-60cd-dd11-93b2-000ea61e65c5;rport
From: "Kyle Johnson" <sip:5003@192.168.2.10>;tag=48e1eb1e-60cd-dd11-93b2-000ea61e65c5
Call-ID: 50d9eb1e-60cd-dd11-93b2-000ea61e65c5@kjohnson-desktop
To: <sip:5003@192.168.2.10>;tag=as6e99f216
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE
Content-Length: 0
Max-Forwards: 70


<------------->
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 0: ACK sip:5003@192.168.2.10 SIP/2.0 (33)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 1: CSeq: 1 ACK (11)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 2: Via: SIP/2.0/UDP 192.168.9.17:5073;branch=z9hG4bK4295f21e-60cd-dd11-93b2-000ea61e65c5;rport (91)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 3: From: "Kyle Johnson" <sip:5003@192.168.2.10>;tag=48e1eb1e-60cd-dd11-93b2-000ea61e65c5 (85)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 4: Call-ID: 50d9eb1e-60cd-dd11-93b2-000ea61e65c5@kjohnson-desktop (62)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 5: To: <sip:5003@192.168.2.10>;tag=as6e99f216 (42)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 6: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE (57)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 7: Content-Length: 0 (17)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 8: Max-Forwards: 70 (16)
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Header 9:  (0)
[Dec 20 19:00:36] VERBOSE[3287] logger.c: --- (9 headers 0 lines) ---
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: = Found Their Call ID: 50d9eb1e-60cd-dd11-93b2-000ea61e65c5@kjohnson-desktop Their Tag 48e1eb1e-60cd-dd11-93b2-000ea61e65c5 Our tag: as6e99f216
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: **** Received ACK (6) - Command in SIP ACK
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #22275
[Dec 20 19:00:36] DEBUG[3287] chan_sip.c: Stopping retransmission on '50d9eb1e-60cd-dd11-93b2-000ea61e65c5@kjohnson-desktop' of Response 1: Match Found
[Dec 20 19:00:36] VERBOSE[3287] logger.c: Really destroying SIP dialog '50d9eb1e-60cd-dd11-93b2-000ea61e65c5@kjohnson-desktop' Method: ACK

bash-3.2#

Then removed debug, and here I am. Is this everything that you needed? It is pretty hard to get the right bits of the log file, when it flyes by so fast!


&nbsp

SkykingOH
Posts: 9677
 Member Since:
2007-12-17
You know you can always ope
Sat, 12/20/2008 - 5:42pm

You know you can always ope the log file with an editor such as nano and then cut and paste the parts you want out of it.

Editing out the secret, not sure that was a great idea. The extension not found is odd since it is registered. The update could have hosed up your permissions.

Try an 'amportal chown' and also 'chmod o+rx agi-bin/ ' and see if that fixes it.

--

Scott

aka "Skyking"


&nbsp

hipan
Posts: 4
 Member Since:
2008-12-20
Tried both the chown and the
Sat, 12/20/2008 - 6:21pm

Tried both the chown and the chmod - neither worked, same error.

I did a "grep 5003 /etc/asterisk/*" and the only lines found were in /etc/asterisk/sip_additional.conf - shouldn't there also be something in the extensions_additional.conf file?


&nbsp

SkykingOH
Posts: 9677
 Member Since:
2007-12-17
Yes there should.... You can
Sat, 12/20/2008 - 6:41pm

Yes there should....

You can open the file with an editor and see what the other peers look like

--

Scott

aka "Skyking"


&nbsp

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.