SPA3102 not registering as an extension

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]
octopus
CLI> 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

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.

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

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.

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

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

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

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.

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