Can't reach extensions and FOP empty

Hello,

I am new to FreePBX and after 3 days fighting I could get Freebox to (almost) work
on an OpenSuse 10 server.

Softphones can register, can call outbound, have audio, save message
to voicemail…

But, very annoying, extensions cannot be reached.

When an extension calls another extension the phone does
not ring and X-Lite displays “Call failed: Declined”. It is not even
routed to the voicemail as expected according to the extension
configuration.

With the announcement set to an extension
when I call 7777 I get the same symptom: call failed,
no voicemail.

With the announcement set to IVR, I get the IVR scenario,
as long as it does not route to an extension.

I copied an extract of the full file below.

I mention that my FreeBox server is connected directly to Internet
(no NAT) and my softphones are behind a router using NAT.
Since I can register my softphones and since I have audio,
I assume that it is not a firewall/router issue.

Aside question:
Since I havn’t added any forwarding rules in the router
I wonder by what magic it does work (sip registration, dial and audio) ?
My understanding is that SIP uses UDP, how these UDP
packets send by the FreePBX server do reach my softphone
across the router ?
I am puzzled. Is my router very clever ?

The second symptom is that FOP remain empty (except for parkings).

Any help would be greatly appreciated

Best Regards
Phil Ten


[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: Set
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [s@macro-user-callerid:8] Set(“SIP/1001-40a02dc8”, “AMPUSERCIDNAME=PHIL1”) in new stack
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: Set
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [s@macro-user-callerid:9] GotoIf(“SIP/1001-40a02dc8”, “0?report”) in new stack
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: GotoIf
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [s@macro-user-callerid:10] Set(“SIP/1001-40a02dc8”, “AMPUSERCID=1001”) in new stack
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: Set
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [s@macro-user-callerid:11] Set(“SIP/1001-40a02dc8”, “CALLERID(all)=“PHIL1” <1001>”) in new stack
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: Set
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [s@macro-user-callerid:12] Set(“SIP/1001-40a02dc8”, “REALCALLERIDNUM=1001”) in new stack
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: Set
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [s@macro-user-callerid:13] NoOp(“SIP/1001-40a02dc8”, “TTL: 64 ARG1: SKIPTTL”) in new stack
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: Noop
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [s@macro-user-callerid:14] GotoIf(“SIP/1001-40a02dc8”, “1?continue”) in new stack
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Goto (macro-user-callerid,s,23)
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: GotoIf
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [s@macro-user-callerid:23] NoOp(“SIP/1001-40a02dc8”, “Using CallerID “PHIL1” <1001>”) in new stack
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: NoOp
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: Macro
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [s@macro-vm:2] Set(“SIP/1001-40a02dc8”, “VMGAIN=”"") in new stack
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: Set
[Nov 26 09:41:13] WARNING[25019] func_db.c: DB requires an argument, DB(/)
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [s@macro-vm:3] GotoIf(“SIP/1001-40a02dc8”, “1?vmx|1”) in new stack
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Goto (macro-vm,vmx,1)
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: GotoIf
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [vmx@macro-vm:1] GotoIf(“SIP/1001-40a02dc8”, “0?s-|1”) in new stack
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: GotoIf
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [vmx@macro-vm:2] Set(“SIP/1001-40a02dc8”, “MODE=unavail”) in new stack
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: Set
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [vmx@macro-vm:3] GotoIf(“SIP/1001-40a02dc8”, “1?notdirect”) in new stack
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Goto (macro-vm,vmx,5)
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: GotoIf
[Nov 26 09:41:13] DEBUG[25019] func_db.c: DB: AMPUSER/1000/vmx/unavail/state not found in database.
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [vmx@macro-vm:5] NoOp(“SIP/1001-40a02dc8”, "Checking if ext 1000 is enabled: ") in new stack
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: Noop
[Nov 26 09:41:13] DEBUG[25019] func_db.c: DB: AMPUSER/1000/vmx/unavail/state not found in database.
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [vmx@macro-vm:6] GotoIf(“SIP/1001-40a02dc8”, “1?s-|1”) in new stack
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Goto (macro-vm,s-,1)
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: GotoIf
[Nov 26 09:41:13] DEBUG[25019] app_macro.c: Executed application: Macro
[Nov 26 09:41:13] VERBOSE[25019] logger.c: – Executing [1000@from-did-direct:2] Hangup(“SIP/1001-40a02dc8”, “”) in new stack
[Nov 26 09:41:13] VERBOSE[25019] logger.c: == Spawn extension (from-did-direct, 1000, 2) exited non-zero on ‘SIP/1001-40a02dc8’
[Nov 26 09:41:13] NOTICE[25019] cdr.c: CDR on channel ‘SIP/1001-40a02dc8’ not posted
[Nov 26 09:44:16] VERBOSE[25072] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Nov 26 09:44:16] VERBOSE[25072] logger.c: Found
[Nov 26 09:44:16] VERBOSE[25072] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Nov 26 09:44:16] VERBOSE[25072] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Nov 26 09:44:17] VERBOSE[25074] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Nov 26 09:44:17] VERBOSE[25074] logger.c: Found

I follow up my previous message to add a network traffic capture grabbed on the
PC (192.168.0.33) running the softphone:

I can see that Asterisk returned a status “603 Declined” in reply to the request.

If someone has an idea on what could cause this reply
it would be great ?

Summary:

No. Time Source Destination Protocol Info
1 0.000000 192.168.0.33 91.121.7.96 SIP/SDP Request: INVITE sip:[email protected], with session description
2 0.055508 91.121.7.96 192.168.0.33 SIP Status: 407 Proxy Authentication Required
3 0.056257 192.168.0.33 91.121.7.96 SIP Request: ACK sip:[email protected]
4 0.057113 192.168.0.33 91.121.7.96 SIP/SDP Request: INVITE sip:[email protected], with session description
5 0.120218 91.121.7.96 192.168.0.33 SIP Status: 100 Trying
6 0.129115 91.121.7.96 192.168.0.33 SIP Status: 603 Declined
7 0.130072 192.168.0.33 91.121.7.96 SIP Request: ACK sip:[email protected]


And with all the details:

No. Time Source Destination Protocol Info
1 0.000000 192.168.0.33 91.121.7.96 SIP/SDP Request: INVITE sip:[email protected], with session description

Frame 1 (946 bytes on wire, 946 bytes captured)
Ethernet II, Src: QuantaCo_99:86:96 (00:16:36:99:86:96), Dst: ZyxelCom_45:1b:b6 (00:a0:c5:45:1b:b6)
Internet Protocol, Src: 192.168.0.33 (192.168.0.33), Dst: 91.121.7.96 (91.121.7.96)
User Datagram Protocol, Src Port: 50796 (50796), Dst Port: 5060 (5060)
Session Initiation Protocol
Request-Line: INVITE sip:[email protected] SIP/2.0
Message Header
Via: SIP/2.0/UDP 192.168.0.33:50796;branch=z9hG4bK-d87543-1272791a9d461f6c-1–d87543-;rport
Max-Forwards: 70
Contact: sip:[email protected]:50796
To: "7777"sip:[email protected]
From: "phil"sip:[email protected];tag=bf36bf30
Call-ID: NmI1OTc2ZWVmZTA2MTNlZTliNmQ0NTE2MzFkNjE3Yzg.
CSeq: 1 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Content-Type: application/sdp
User-Agent: X-Lite release 1011s stamp 41150
Content-Length: 370
Message body
Session Description Protocol
Session Description Protocol Version (v): 0
Owner/Creator, Session Id (o): - 9 2 IN IP4 192.168.0.33
Session Name (s): CounterPath X-Lite 3.0
Connection Information ©: IN IP4 192.168.0.33
Time Description, active time (t): 0 0
Media Description, name and address (m): audio 46310 RTP/AVP 107 119 100 106 0 105 98 8 101
Media Attribute (a): fmtp:101 0-15
Media Attribute (a): rtpmap:107 BV32/16000
Media Attribute (a): rtpmap:119 BV32-FEC/16000
Media Attribute (a): rtpmap:100 SPEEX/16000
Media Attribute (a): rtpmap:106 SPEEX-FEC/16000
Media Attribute (a): rtpmap:105 SPEEX-FEC/8000
Media Attribute (a): rtpmap:98 iLBC/8000
Media Attribute (a): rtpmap:101 telephone-event/8000
Media Attribute (a): sendrecv

No. Time Source Destination Protocol Info
2 0.055508 91.121.7.96 192.168.0.33 SIP Status: 407 Proxy Authentication Required

Frame 2 (596 bytes on wire, 596 bytes captured)
Ethernet II, Src: ZyxelCom_45:1b:b6 (00:a0:c5:45:1b:b6), Dst: QuantaCo_99:86:96 (00:16:36:99:86:96)
Internet Protocol, Src: 91.121.7.96 (91.121.7.96), Dst: 192.168.0.33 (192.168.0.33)
User Datagram Protocol, Src Port: 5060 (5060), Dst Port: 50796 (50796)
Session Initiation Protocol
Status-Line: SIP/2.0 407 Proxy Authentication Required
Message Header
Via: SIP/2.0/UDP 192.168.0.33:50796;branch=z9hG4bK-d87543-1272791a9d461f6c-1–d87543-;received=82.234.125.20;rport=10522
From: "phil"sip:[email protected];tag=bf36bf30
To: "7777"sip:[email protected];tag=as04689863
Call-ID: NmI1OTc2ZWVmZTA2MTNlZTliNmQ0NTE2MzFkNjE3Yzg.
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="6143c581"
Content-Length: 0

No. Time Source Destination Protocol Info
3 0.056257 192.168.0.33 91.121.7.96 SIP Request: ACK sip:[email protected]

Frame 3 (365 bytes on wire, 365 bytes captured)
Ethernet II, Src: QuantaCo_99:86:96 (00:16:36:99:86:96), Dst: ZyxelCom_45:1b:b6 (00:a0:c5:45:1b:b6)
Internet Protocol, Src: 192.168.0.33 (192.168.0.33), Dst: 91.121.7.96 (91.121.7.96)
User Datagram Protocol, Src Port: 50796 (50796), Dst Port: 5060 (5060)
Session Initiation Protocol
Request-Line: ACK sip:[email protected] SIP/2.0
Message Header
Via: SIP/2.0/UDP 192.168.0.33:50796;branch=z9hG4bK-d87543-1272791a9d461f6c-1–d87543-;rport
To: "7777"sip:[email protected];tag=as04689863
From: "phil"sip:[email protected];tag=bf36bf30
Call-ID: NmI1OTc2ZWVmZTA2MTNlZTliNmQ0NTE2MzFkNjE3Yzg.
CSeq: 1 ACK
Content-Length: 0

No. Time Source Destination Protocol Info
4 0.057113 192.168.0.33 91.121.7.96 SIP/SDP Request: INVITE sip:[email protected], with session description

Frame 4 (1113 bytes on wire, 1113 bytes captured)
Ethernet II, Src: QuantaCo_99:86:96 (00:16:36:99:86:96), Dst: ZyxelCom_45:1b:b6 (00:a0:c5:45:1b:b6)
Internet Protocol, Src: 192.168.0.33 (192.168.0.33), Dst: 91.121.7.96 (91.121.7.96)
User Datagram Protocol, Src Port: 50796 (50796), Dst Port: 5060 (5060)
Session Initiation Protocol
Request-Line: INVITE sip:[email protected] SIP/2.0
Message Header
Via: SIP/2.0/UDP 192.168.0.33:50796;branch=z9hG4bK-d87543-f144b92a31443d51-1–d87543-;rport
Max-Forwards: 70
Contact: sip:[email protected]:50796
To: "7777"sip:[email protected]
From: “phil"sip:[email protected];tag=bf36bf30
Call-ID: NmI1OTc2ZWVmZTA2MTNlZTliNmQ0NTE2MzFkNjE3Yzg.
CSeq: 2 INVITE
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO
Content-Type: application/sdp
Proxy-Authorization: Digest username=“1001”,realm=“asterisk”,nonce=“6143c581”,uri="sip:[email protected]”,response=“ee12e39dba2cd053283b152cfbfb7d99”,algorithm=MD5
User-Agent: X-Lite release 1011s stamp 41150
Content-Length: 370
Message body
Session Description Protocol
Session Description Protocol Version (v): 0
Owner/Creator, Session Id (o): - 9 2 IN IP4 192.168.0.33
Session Name (s): CounterPath X-Lite 3.0
Connection Information ©: IN IP4 192.168.0.33
Time Description, active time (t): 0 0
Media Description, name and address (m): audio 46310 RTP/AVP 107 119 100 106 0 105 98 8 101
Media Attribute (a): fmtp:101 0-15
Media Attribute (a): rtpmap:107 BV32/16000
Media Attribute (a): rtpmap:119 BV32-FEC/16000
Media Attribute (a): rtpmap:100 SPEEX/16000
Media Attribute (a): rtpmap:106 SPEEX-FEC/16000
Media Attribute (a): rtpmap:105 SPEEX-FEC/8000
Media Attribute (a): rtpmap:98 iLBC/8000
Media Attribute (a): rtpmap:101 telephone-event/8000
Media Attribute (a): sendrecv

No. Time Source Destination Protocol Info
5 0.120218 91.121.7.96 192.168.0.33 SIP Status: 100 Trying

Frame 5 (513 bytes on wire, 513 bytes captured)
Ethernet II, Src: ZyxelCom_45:1b:b6 (00:a0:c5:45:1b:b6), Dst: QuantaCo_99:86:96 (00:16:36:99:86:96)
Internet Protocol, Src: 91.121.7.96 (91.121.7.96), Dst: 192.168.0.33 (192.168.0.33)
User Datagram Protocol, Src Port: 5060 (5060), Dst Port: 50796 (50796)
Session Initiation Protocol
Status-Line: SIP/2.0 100 Trying
Message Header
Via: SIP/2.0/UDP 192.168.0.33:50796;branch=z9hG4bK-d87543-f144b92a31443d51-1–d87543-;received=82.234.125.20;rport=10522
From: "phil"sip:[email protected];tag=bf36bf30
To: "7777"sip:[email protected]
Call-ID: NmI1OTc2ZWVmZTA2MTNlZTliNmQ0NTE2MzFkNjE3Yzg.
CSeq: 2 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: sip:[email protected]
Content-Length: 0

No. Time Source Destination Protocol Info
6 0.129115 91.121.7.96 192.168.0.33 SIP Status: 603 Declined

Frame 6 (530 bytes on wire, 530 bytes captured)
Ethernet II, Src: ZyxelCom_45:1b:b6 (00:a0:c5:45:1b:b6), Dst: QuantaCo_99:86:96 (00:16:36:99:86:96)
Internet Protocol, Src: 91.121.7.96 (91.121.7.96), Dst: 192.168.0.33 (192.168.0.33)
User Datagram Protocol, Src Port: 5060 (5060), Dst Port: 50796 (50796)
Session Initiation Protocol
Status-Line: SIP/2.0 603 Declined
Message Header
Via: SIP/2.0/UDP 192.168.0.33:50796;branch=z9hG4bK-d87543-f144b92a31443d51-1–d87543-;received=82.234.125.20;rport=10522
From: "phil"sip:[email protected];tag=bf36bf30
To: "7777"sip:[email protected];tag=as2ca14564
Call-ID: NmI1OTc2ZWVmZTA2MTNlZTliNmQ0NTE2MzFkNjE3Yzg.
CSeq: 2 INVITE
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: sip:[email protected]
Content-Length: 0

No. Time Source Destination Protocol Info
7 0.130072 192.168.0.33 91.121.7.96 SIP Request: ACK sip:[email protected]

Frame 7 (365 bytes on wire, 365 bytes captured)
Ethernet II, Src: QuantaCo_99:86:96 (00:16:36:99:86:96), Dst: ZyxelCom_45:1b:b6 (00:a0:c5:45:1b:b6)
Internet Protocol, Src: 192.168.0.33 (192.168.0.33), Dst: 91.121.7.96 (91.121.7.96)
User Datagram Protocol, Src Port: 50796 (50796), Dst Port: 5060 (5060)
Session Initiation Protocol
Request-Line: ACK sip:[email protected] SIP/2.0
Message Header
Via: SIP/2.0/UDP 192.168.0.33:50796;branch=z9hG4bK-d87543-f144b92a31443d51-1–d87543-;rport
To: "7777"sip:[email protected];tag=as2ca14564
From: "phil"sip:[email protected];tag=bf36bf30
Call-ID: NmI1OTc2ZWVmZTA2MTNlZTliNmQ0NTE2MzFkNjE3Yzg.
CSeq: 2 ACK
Content-Length: 0

I finally could understand and solve this issue by launching Asterisk in verbose mode.

The problem was a wrong path for php in script “dialparties.agi”.

Phil