SPA3102 not registering as an extension

dibble5504 · December 15, 2008, 10:25am

Hi,

I have been having a problem with my Asterisk / FreePBX setup since last week that is driving me mad. I use an SPA3102 as a local extension and inbound / outbound PSTN line. The PSTN functionality is working fine (but rarely used as VoIP is the default trunk).

The problem is that the SPA3102 is not registering properly as a local extension. Incoming trunk calls are going straight to voicemail and direct calls are failing. Ekiga flashes “Remote user rejected the call”.

The device claims to be registered and Asterisk also shows OK:
Connected to Asterisk 1.4.17~dfsg-2ubuntu1 currently running on octopus (pid = 4262) octopusCLI> sip show peers Name/username Host Dyn Nat ACL Port Status SPA3102_Out 192.168.1.90 5061 OK (5 ms) SIPGate/2#####0 217.10.79.23 N 5060 OK (346 ms) MyNetFone/0######1 125.213.160.81 N 5060 OK (46 ms) 203/203 192.168.1.121 D N 5061 OK (1 ms) 202 (Unspecified) D N 0 UNKNOWN 201/201 (Unspecified) D 0 UNKNOWN 200/200 192.168.1.90 D 5060 OK (5 ms) 7 sip peers [Monitored: 5 online, 2 offline Unmonitored: 0 online, 0 offline] octopusCLI> sip show users Username Secret Accountcode Def.Context ACL NAT SPA3102_In from-trunk No RFC3581 2#####0 ######## from-trunk No RFC3581 203 ###### from-internal No Always 202 ###### from-internal No Always 201 ###### from-internal No RFC3581 200 ###### from-internal No RFC3581 0######1 ######## from-trunk No RFC3581

The following is the SIP debug trace. You will see a couple of 401 and 404 errors. Google isn’t providing a solution and I am all out of ideas.


[Dec 15 19:17:57] VERBOSE[4538] logger.c:
<--- SIP read from 192.168.1.90:5060 --->
SUBSCRIBE sip:192.168.1.88 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.90:5060;branch=z9hG4bK-9ffbecbb;rport
From: SPA3102 ;tag=fada3acf1ea124a6
To: SPA3102 
Call-ID: [email protected]
CSeq: 11160 SUBSCRIBE
Max-Forwards: 70
Authorization: Digest username="200",realm="asterisk",nonce="7ec13917",uri="sip:192.168.1.88",algorithm=MD5,response="411e39c4ab7e6223eab6731e98170108"
Contact: SPA3102 
Expires: 2147483647
Event: message-summary
User-Agent: Linksys/SPA3102-5.1.5(GWa)
Content-Length: 0
<------------->

[Dec 15 19:17:57] VERBOSE[4538] logger.c: — (13 headers 0 lines) —

[Dec 15 19:17:57] VERBOSE[4538] logger.c: Creating new subscription

[Dec 15 19:17:57] VERBOSE[4538] logger.c: Sending to 192.168.1.90 : 5060 (NAT)

[Dec 15 19:17:57] VERBOSE[4538] logger.c: Found peer ‘200’

[Dec 15 19:17:57] VERBOSE[4538] logger.c:

<— Transmitting (no NAT) to 192.168.1.90:5060 —>

SIP/2.0 401 Unauthorized

Via: SIP/2.0/UDP 192.168.1.90:5060;branch=z9hG4bK-9ffbecbb;received=192.168.1.90;rport=5060

From: SPA3102 sip:[email protected];tag=fada3acf1ea124a6

To: SPA3102 sip:[email protected];tag=as3edbe5f6

Call-ID: [email protected]

CSeq: 11160 SUBSCRIBE

User-Agent: Asterisk PBX

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY

Supported: replaces

WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce="3df5997f"

Content-Length: 0
<------------>

[Dec 15 19:17:57] VERBOSE[4538] logger.c: Scheduling destruction of SIP dialog ‘[email protected]’ in 6400 ms (Method: SUBSCRIBE)

[Dec 15 19:17:57] VERBOSE[4538] logger.c:

<— SIP read from 192.168.1.90:5060 —>

SUBSCRIBE sip:192.168.1.88 SIP/2.0

Via: SIP/2.0/UDP 192.168.1.90:5060;branch=z9hG4bK-4692b97b;rport

From: SPA3102 sip:[email protected];tag=fada3acf1ea124a6

To: SPA3102 sip:[email protected]

Call-ID: [email protected]

CSeq: 11161 SUBSCRIBE

Max-Forwards: 70

Authorization: Digest username=“200”,realm=“asterisk”,nonce=“3df5997f”,uri=“sip:192.168.1.88”,algorithm=MD5,response="9a04c3b03da660e9d584beef81181f6e"

Contact: SPA3102 sip:[email protected]:5060

Expires: 2147483647

Event: message-summary

User-Agent: Linksys/SPA3102-5.1.5(GWa)

Content-Length: 0
<------------->

[Dec 15 19:17:57] VERBOSE[4538] logger.c: — (13 headers 0 lines) —

[Dec 15 19:17:57] VERBOSE[4538] logger.c: Creating new subscription

[Dec 15 19:17:57] VERBOSE[4538] logger.c: Sending to 192.168.1.90 : 5060 (NAT)

[Dec 15 19:17:57] VERBOSE[4538] logger.c: Found peer ‘200’

[Dec 15 19:17:57] VERBOSE[4538] logger.c: Looking for s in from-internal (domain 192.168.1.88)

[Dec 15 19:17:57] VERBOSE[4538] logger.c:

<— Transmitting (no NAT) to 192.168.1.90:5060 —>

SIP/2.0 404 Not Found

Via: SIP/2.0/UDP 192.168.1.90:5060;branch=z9hG4bK-4692b97b;received=192.168.1.90;rport=5060

From: SPA3102 sip:[email protected];tag=fada3acf1ea124a6

To: SPA3102 sip:[email protected];tag=as3edbe5f6

Call-ID: [email protected]

CSeq: 11161 SUBSCRIBE

User-Agent: Asterisk PBX

Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY

Supported: replaces

Content-Length: 0
<------------>

[Dec 15 19:17:57] VERBOSE[4538] logger.c: Really destroying SIP dialog ‘[email protected]’ Method: SUBSCRIBE

[Dec 15 19:18:01] WARNING[7205] func_db.c: DB requires an argument, DB(/)

Thanks,

Paul

wiseoldowl · December 15, 2008, 11:43am

You didn’t really make it crystal clear whether the problem is on Line 1 or the PSTN line. But if it’s a problem with incoming calls on the PSTN line, as your post suggests, then I suggest you start here:

http://www.freepbx.org/support/documentation/howtos/howto-linksys-spa-3102-sipura-spa-3000-freepbx

Follow the instructions there and it should work.

dibble5504 · December 15, 2008, 9:44pm

Thanks for your reply.

PSTN is working 100% OK. The problem is with calling the extension. I can use the extension to call other extensions and trunks, but calls to the extension are rejected.

I have already read the post you suggested but it didn’t apply to my problem.

Hope this clarifies.

Paul

jmullinix · December 15, 2008, 10:19pm

Paul,

This looks like an authentication issue. You have the ports set differently on the two interfaces, which is good. If you have a username in the SPA setup, make sure you have one in your FreePBX setup for that extension and make sure the passwords match.

dibble5504 · December 15, 2008, 10:34pm

The 401 error certainly suggests authentication as the problem. The SPA3102 is authenticating as user 200, but also has SPA3102 as the name. FreePBX does not have SPA3102 as the alias for this device so I will try changing that and let you know.

Thanks for the quick response.

Paul

dibble5504 · December 16, 2008, 2:37am

I’ve checked the FreePBX settings to for username, secret/password and descriptive names. Everything matches and seems OK.

As mentioned in my first post, the device and Asterisk sees the extension as being registered. When I call the extension, the SIP trace shows the 401 Unauthorized error and then 404 Not Found.

Any other ideas?

Paul

dibble5504 · December 16, 2008, 9:51am

I’ve reset the SPA3102 to factory defaults and entered ONLY the SIP registration details. The device registers, but the calls are still rejected.

After a bit more digging in the Asterisk CLI, I found the following trace:

– Executing [200@from-internal:1] Macro(“SIP/203-0824b448”, “exten-vm|200|200”) in new stack – Executing [s@macro-exten-vm:1] Macro(“SIP/203-0824b448”, “user-callerid”) in new stack – Executing [s@macro-user-callerid:1] Set(“SIP/203-0824b448”, “AMPUSER=203”) in new stack – Executing [s@macro-user-callerid:2] GotoIf(“SIP/203-0824b448”, “0?report”) in new stack – Executing [s@macro-user-callerid:3] ExecIf(“SIP/203-0824b448”, “1|Set|REALCALLERIDNUM=203”) in new stack – Executing [s@macro-user-callerid:4] Set(“SIP/203-0824b448”, “AMPUSER=203”) in new stack – Executing [s@macro-user-callerid:5] Set(“SIP/203-0824b448”, “AMPUSERCIDNAME=PC Phone”) in new stack – Executing [s@macro-user-callerid:6] GotoIf(“SIP/203-0824b448”, “0?report”) in new stack – Executing [s@macro-user-callerid:7] Set(“SIP/203-0824b448”, “AMPUSERCID=203”) in new stack – Executing [s@macro-user-callerid:8] Set(“SIP/203-0824b448”, “CALLERID(all)=“PC Phone” <203>”) in new stack – Executing [s@macro-user-callerid:9] Set(“SIP/203-0824b448”, “REALCALLERIDNUM=203”) in new stack – Executing [s@macro-user-callerid:10] GotoIf(“SIP/203-0824b448”, “0?continue”) in new stack – Executing [s@macro-user-callerid:11] Set(“SIP/203-0824b448”, “__TTL=64”) in new stack – Executing [s@macro-user-callerid:12] GotoIf(“SIP/203-0824b448”, “1?continue”) in new stack – Goto (macro-user-callerid,s,19) – Executing [s@macro-user-callerid:19] NoOp(“SIP/203-0824b448”, “Using CallerID “PC Phone” <203>”) in new stack – Executing [s@macro-exten-vm:2] Set(“SIP/203-0824b448”, “RingGroupMethod=none”) in new stack – Executing [s@macro-exten-vm:3] Set(“SIP/203-0824b448”, “VMBOX=200”) in new stack – Executing [s@macro-exten-vm:4] Set(“SIP/203-0824b448”, “EXTTOCALL=200”) in new stack – Executing [s@macro-exten-vm:5] Set(“SIP/203-0824b448”, “CFUEXT=”) in new stack – Executing [s@macro-exten-vm:6] Set(“SIP/203-0824b448”, “CFBEXT=”) in new stack – Executing [s@macro-exten-vm:7] Set(“SIP/203-0824b448”, “RT=15”) in new stack – Executing [s@macro-exten-vm:8] Macro(“SIP/203-0824b448”, “record-enable|200|IN”) in new stack – Executing [s@macro-record-enable:1] GotoIf(“SIP/203-0824b448”, “1?check”) in new stack – Goto (macro-record-enable,s,4) – Executing [s@macro-record-enable:4] AGI(“SIP/203-0824b448”, “recordingcheck|20081216-203731|asterisk-4262-1229420251.121”) in new stack – Launched AGI Script /usr/share/asterisk/agi-bin/recordingcheck == recordingcheck|20081216-203731|asterisk-4262-1229420251.121: Failed to execute ‘/usr/share/asterisk/agi-bin/recordingcheck’: Permission denied – AGI Script recordingcheck completed, returning 0 – Executing [s@macro-record-enable:5] MacroExit(“SIP/203-0824b448”, “”) in new stack – Executing [s@macro-exten-vm:9] Macro(“SIP/203-0824b448”, “dial|15|tr|200”) in new stack – Executing [s@macro-dial:1] GotoIf(“SIP/203-0824b448”, “1?dial”) in new stack – Goto (macro-dial,s,3) – Executing [s@macro-dial:3] AGI(“SIP/203-0824b448”, “dialparties.agi”) in new stack – Launched AGI Script /usr/share/asterisk/agi-bin/dialparties.agi == dialparties.agi: Failed to execute ‘/usr/share/asterisk/agi-bin/dialparties.agi’: Permission denied – AGI Script dialparties.agi completed, returning 0 – Executing [s@macro-dial:4] NoOp(“SIP/203-0824b448”, “Returned from dialparties with no extensions to call and DIALSTATUS: “) in new stack – Executing [s@macro-exten-vm:10] GotoIf(“SIP/203-0824b448”, “0?exit|return”) in new stack – Executing [s@macro-exten-vm:11] Set(“SIP/203-0824b448”, “SV_DIALSTATUS=”) in new stack – Executing [s@macro-exten-vm:12] GosubIf(“SIP/203-0824b448”, “0?docfu|1”) in new stack – Executing [s@macro-exten-vm:13] GosubIf(“SIP/203-0824b448”, “0?docfb|1”) in new stack – Executing [s@macro-exten-vm:14] Set(“SIP/203-0824b448”, “DIALSTATUS=”) in new stack – Executing [s@macro-exten-vm:15] NoOp(“SIP/203-0824b448”, “Voicemail is 200”) in new stack – Executing [s@macro-exten-vm:16] GotoIf(“SIP/203-0824b448”, “0?s-|1”) in new stack – Executing [s@macro-exten-vm:17] NoOp(“SIP/203-0824b448”, “Sending to Voicemail box 200”) in new stack – Executing [s@macro-exten-vm:18] Macro(“SIP/203-0824b448”, “vm|200||”) in new stack – Executing [s@macro-vm:1] Macro(“SIP/203-0824b448”, “user-callerid|SKIPTTL”) in new stack – Executing [s@macro-user-callerid:1] Set(“SIP/203-0824b448”, “AMPUSER=203”) in new stack – Executing [s@macro-user-callerid:2] GotoIf(“SIP/203-0824b448”, “0?report”) in new stack – Executing [s@macro-user-callerid:3] ExecIf(“SIP/203-0824b448”, “0|Set|REALCALLERIDNUM=203”) in new stack – Executing [s@macro-user-callerid:4] Set(“SIP/203-0824b448”, “AMPUSER=203”) in new stack – Executing [s@macro-user-callerid:5] Set(“SIP/203-0824b448”, “AMPUSERCIDNAME=PC Phone”) in new stack – Executing [s@macro-user-callerid:6] GotoIf(“SIP/203-0824b448”, “0?report”) in new stack – Executing [s@macro-user-callerid:7] Set(“SIP/203-0824b448”, “AMPUSERCID=203”) in new stack – Executing [s@macro-user-callerid:8] Set(“SIP/203-0824b448”, “CALLERID(all)=“PC Phone” <203>”) in new stack – Executing [s@macro-user-callerid:9] Set(“SIP/203-0824b448”, “REALCALLERIDNUM=203”) in new stack – Executing [s@macro-user-callerid:10] GotoIf(“SIP/203-0824b448”, “1?continue”) in new stack – Goto (macro-user-callerid,s,19) – Executing [s@macro-user-callerid:19] NoOp(“SIP/203-0824b448”, “Using CallerID “PC Phone” <203>”) in new stack – Executing [s@macro-vm:2] Set(“SIP/203-0824b448”, “VMGAIN=”””) in new stack – Executing [s@macro-vm:3] GotoIf(“SIP/203-0824b448”, “1?vmx|1”) in new stack – Goto (macro-vm,vmx,1) – Executing [vmx@macro-vm:1] GotoIf(“SIP/203-0824b448”, “0?s-|1”) in new stack – Executing [vmx@macro-vm:2] Set(“SIP/203-0824b448”, “MODE=unavail”) in new stack – Executing [vmx@macro-vm:3] GotoIf(“SIP/203-0824b448”, “1?notdirect”) in new stack – Goto (macro-vm,vmx,5) – Executing [vmx@macro-vm:5] NoOp(“SIP/203-0824b448”, "Checking if ext 200 is enabled: ") in new stack – Executing [vmx@macro-vm:6] GotoIf(“SIP/203-0824b448”, “1?s-|1”) in new stack – Goto (macro-vm,s-,1) – Executing [200@from-internal:2] Goto(“SIP/203-0824b448”, “vmret|1”) in new stack – Goto (from-internal,vmret,1) – Executing [vmret@from-internal:1] GotoIf(“SIP/203-0824b448”, “0?playret”) in new stack – Executing [vmret@from-internal:2] Hangup(“SIP/203-0824b448”, “”) in new stack == Spawn extension (from-internal, vmret, 2) exited non-zero on ‘SIP/203-0824b448’ – Executing [h@from-internal:1] Macro(“SIP/203-0824b448”, “hangupcall”) in new stack – Executing [s@macro-hangupcall:1] ResetCDR(“SIP/203-0824b448”, “w”) in new stack – Executing [s@macro-hangupcall:2] NoCDR(“SIP/203-0824b448”, “”) in new stack – Executing [s@macro-hangupcall:3] GotoIf(“SIP/203-0824b448”, “1?skiprg”) in new stack – Goto (macro-hangupcall,s,6) – Executing [s@macro-hangupcall:6] GotoIf(“SIP/203-0824b448”, “1?skipblkvm”) in new stack – Goto (macro-hangupcall,s,9) – Executing [s@macro-hangupcall:9] GotoIf(“SIP/203-0824b448”, “1?theend”) in new stack – Goto (macro-hangupcall,s,11) – Executing [s@macro-hangupcall:11] Hangup(“SIP/203-0824b448”, “”) in new stack == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘SIP/203-0824b448’ in macro ‘hangupcall’ == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘SIP/203-0824b448’

From what I can tell, there is a problem with the AGI scripts. When FreePBX installed itself, many of the AGI scripts were in the /var/www/admin/modules/core/agi-bin/ directory. I moved them to /usr/share/asterisk/agi-bin/ which is where it was looking for them. File permissions were asterisk:asterisk 775 but I’ve changed to root:root 744 which is the same as the two files that were already there. Both file permissions give the same errors in the CLI.

I’m not sure why these files are erroring out with Permission Denied. Can anyone shed any light?

Thanks in advance.

Paul

dibble5504 · December 16, 2008, 10:00am

I have just tried chmod +x * in the AGI scipts directory as I realised that the asterisk user didn’t have execute rights. No effect.

dibble5504 · December 16, 2008, 10:29am

Had to think a little bigger than the file permissions. The directory permissions were a bit harsh. chmod o+rx agi-bin/ solved the problem.

Paul