100+ extension do not work ?! some limitation somewhere?

arhi · July 17, 2018, 5:50pm

99-100 extension worked flawlesly, today I added 5 new phones and they don’t work

all the extensions are configured identical (chan_sip)
phones properly register to the system
I can see the extension on the phone as it registered correctly
I can dial out from this phone(s) normally
when I try to call this phone it does not ring, I hear busy tone and get info “service unaviable” on dialer phone
I turn off one of the phones from working 100 extensions, give this new phone extension of the phone it works (I just change the mac.cfg file to change extension number and reset the phone) and it works flawlesly as the “old” extension, I return to new extension and it does not work

I spent 2 days already on this without a clue what’s going on, phone configuration is delivered trough tftpd and almost all phones are same, config files are same the only difference is extension number… and what’s weird is that 99 or 100 extensions worked and when I added these new ones it stopped, like there’s some limit for something at 100 extensions???

something from log (300 is the “non working” extension, can dial out, can’t be called)

[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.1.201:5066:
INVITE sip:[email protected]:5066 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK0b4358fc
Max-Forwards: 70
From: "473" <sip:[email protected]>;tag=as7583f89d
To: <sip:[email protected]:5066>
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 INVITE
User-Agent: FPBX-13.0.195.4(13.18.3)
Date: Tue, 17 Jul 2018 14:15:53 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Type: application/sdp
Content-Length: 328

v=0
o=root 146894188 146894188 IN IP4 192.168.1.10
s=Asterisk PBX 13.18.3
c=IN IP4 192.168.1.10
t=0 0
m=audio 10112 RTP/AVP 0 8 3 111 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:111 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

---
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] app_dial.c: Called SIP/300
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] app_dial.c: Connected line update to SIP/473-00270659 prevented.
[2018-07-17 16:15:53] VERBOSE[3058] chan_sip.c:
<--- SIP read from UDP:192.168.1.201:5066 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK0b4358fc
From: "473" <sip:[email protected]>;tag=as7583f89d
To: <sip:[email protected]:5066>
Call-ID: [email protected]:5060
CSeq: 102 INVITE
User-Agent: Yealink SIP-T19P 31.72.0.75
Content-Length: 0

<------------->
[2018-07-17 16:15:53] VERBOSE[3058] chan_sip.c: --- (8 headers 0 lines) ---
[2018-07-17 16:15:53] VERBOSE[24970][C-00058a99] bridge_channel.c: Channel SIP/490-00270633 left 'simple_bridge' basic-bridge <35702a28-f9ab-4b08-af57-3038700bc995>
[2018-07-17 16:15:53] VERBOSE[24970][C-00058a99] app_macro.c: Spawn extension (macro-dialout-trunk, s, 24) exited non-zero on 'SIP/490-00270633' in macro 'dialout-trunk'
[2018-07-17 16:15:53] VERBOSE[24970][C-00058a99] pbx.c: Spawn extension (from-internal, 18006931779, 7) exited non-zero on 'SIP/490-00270633'
[2018-07-17 16:15:53] VERBOSE[24970][C-00058a99] pbx.c: Executing [h@from-internal:1] Macro("SIP/490-00270633", "hangupcall") in new stack
[2018-07-17 16:15:53] VERBOSE[24970][C-00058a99] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/490-00270633", "1?theend") in new stack
[2018-07-17 16:15:53] VERBOSE[24970][C-00058a99] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2018-07-17 16:15:53] VERBOSE[24981][C-00058a99] bridge_channel.c: Channel SIP/FlowRouteTrunk-00270634 left 'simple_bridge' basic-bridge <35702a28-f9ab-4b08-af57-3038700bc995>
[2018-07-17 16:15:53] VERBOSE[24970][C-00058a99] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/490-00270633", "0?Set(CDR(recordingfile)=)") in new stack
[2018-07-17 16:15:53] VERBOSE[24970][C-00058a99] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/490-00270633", "") in new stack
[2018-07-17 16:15:53] VERBOSE[24970][C-00058a99] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/490-00270633' in macro 'hangupcall'
[2018-07-17 16:15:53] VERBOSE[24970][C-00058a99] pbx.c: Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/490-00270633'
[2018-07-17 16:15:53] VERBOSE[24971][C-00058a99] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2018-07-17 16:15:53] VERBOSE[24971][C-00058a99] app_mixmonitor.c: End MixMonitor Recording SIP/490-00270633
[2018-07-17 16:15:53] VERBOSE[3058] chan_sip.c:
<--- SIP read from UDP:192.168.1.201:5066 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK0b4358fc
From: "473" <sip:[email protected]>;tag=as7583f89d
To: <sip:[email protected]:5066>;tag=1376329631
Call-ID: [email protected]:5060
CSeq: 102 INVITE
Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE
User-Agent: Yealink SIP-T19P 31.72.0.75
Allow-Events: talk,hold,conference,refer,check-sync
Content-Length: 0

<------------->
[2018-07-17 16:15:53] VERBOSE[3058] chan_sip.c: --- (10 headers 0 lines) ---
[2018-07-17 16:15:53] VERBOSE[3058][C-00058aa7] chan_sip.c: Transmitting (no NAT) to 192.168.1.201:5066:
ACK sip:[email protected]:5066 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK0b4358fc
Max-Forwards: 70
From: "473" <sip:[email protected]>;tag=as7583f89d
To: <sip:[email protected]:5066>;tag=1376329631
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 ACK
User-Agent: FPBX-13.0.195.4(13.18.3)
Content-Length: 0

---
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] chan_sip.c: Scheduling destruction of SIP dialog '[email protected]:5060' in 6400 ms (Method: INVITE)
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] app_dial.c: Everyone is busy/congested at this time (1:0/0/1)
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s@macro-dial-one:55] ExecIf("SIP/473-00270659", "0?MacroExit()") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s@macro-dial-one:56] ExecIf("SIP/473-00270659", "0?Set(DIALSTATUS=)") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s@macro-dial-one:57] GosubIf("SIP/473-00270659", "0?s-CHANUNAVAIL,1()") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s@macro-dial-one:58] MacroExit("SIP/473-00270659", "") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s@macro-exten-vm:27] Set("SIP/473-00270659", "SV_DIALSTATUS=CHANUNAVAIL") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s@macro-exten-vm:28] GosubIf("SIP/473-00270659", "0?docfu,1()") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s@macro-exten-vm:29] GosubIf("SIP/473-00270659", "0?docfb,1()") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s@macro-exten-vm:30] Set("SIP/473-00270659", "DIALSTATUS=CHANUNAVAIL") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s@macro-exten-vm:31] ExecIf("SIP/473-00270659", "0?MacroExit()") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s@macro-exten-vm:32] GotoIf("SIP/473-00270659", "1?s-CHANUNAVAIL,1") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx_builtins.c: Goto (macro-exten-vm,s-CHANUNAVAIL,1)
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s-CHANUNAVAIL@macro-exten-vm:1] GotoIf("SIP/473-00270659", "0?exit,1") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s-CHANUNAVAIL@macro-exten-vm:2] PlayTones("SIP/473-00270659", "congestion") in new stack
[2018-07-17 16:15:53] WARNING[25160][C-00058aa7] translate.c: no samples for ulawtolin
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s-CHANUNAVAIL@macro-exten-vm:3] Congestion("SIP/473-00270659", "10") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] app_macro.c: Spawn extension (macro-exten-vm, s-CHANUNAVAIL, 3) exited non-zero on 'SIP/473-00270659' in macro 'exten-vm'
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Spawn extension (ext-local, 300, 2) exited non-zero on 'SIP/473-00270659'
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [h@ext-local:1] Macro("SIP/473-00270659", "hangupcall,") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s@macro-hangupcall:1] GotoIf("SIP/473-00270659", "1?theend") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s@macro-hangupcall:3] ExecIf("SIP/473-00270659", "0?Set(CDR(recordingfile)=)") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Executing [s@macro-hangupcall:4] Hangup("SIP/473-00270659", "") in new stack
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/473-00270659' in macro 'hangupcall'
[2018-07-17 16:15:53] VERBOSE[25160][C-00058aa7] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/473-00270659'
[2018-07-17 16:15:53] VERBOSE[25165][C-00058aa7] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2018-07-17 16:15:53] VERBOSE[25165][C-00058aa7] app_mixmonitor.c: End MixMonitor Recording SIP/473-00270659
[2018-07-17 16:15:56] VERBOSE[3058] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.1.201:5066:
OPTIONS sip:[email protected]:5066 SIP/2.0
Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK60a50198
Max-Forwards: 70
From: "Unknown" <sip:[email protected]>;tag=as03f60119
To: <sip:[email protected]:5066>
Contact: <sip:[email protected]:5060>
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
User-Agent: FPBX-13.0.195.4(13.18.3)
Date: Tue, 17 Jul 2018 14:15:56 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0
---
[2018-07-17 16:15:56] VERBOSE[3058] chan_sip.c:
<--- SIP read from UDP:192.168.1.201:5066 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.10:5060;branch=z9hG4bK60a50198
From: "Unknown" <sip:[email protected]>;tag=as03f60119
To: <sip:[email protected]:5066>;tag=335340994
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
User-Agent: Yealink SIP-T19P 31.72.0.75
Content-Length: 0

<------------->
[2018-07-17 16:15:56] VERBOSE[3058] chan_sip.c: --- (8 headers 0 lines) ---
[2018-07-17 16:15:56] VERBOSE[3058] chan_sip.c: Really destroying SIP dialog '[email protected]:5060' Method: OPTIONS
[2018-07-17 16:15:58] VERBOSE[25139][C-00058aa2] app_macro.c: Spawn extension (macro-dialout-trunk, s, 24) exited non-zero on 'SIP/429-0027064f' in macro 'dialout-trunk'
...

I have no clue how to read this log I kinda turned on debug on the ip of that extension but no clue what’s going on here nor how to go forward … any help is highly appreciated

arhi · July 17, 2018, 5:52pm

the things that look like an issue to me here are

Connected line update to SIP/473-00270659 prevented

and

Everyone is busy/congested at this time (1:0/0/1)

neither makes sense to me

gbaughma · July 27, 2018, 7:02pm

It looks to me like the phone isn’t registered… I could be wrong… but the “unknown” caught my eye.

arhi · July 27, 2018, 7:15pm

dunno, weird stuff is happening, they all (phones) show they are registered … sip show peers shows them all properly registered … and then they don’t work… worst part, they start working out of nowhere and then other phones stop working (that were working for year+) … like there’s a limit on number of working phones … I’m not getting it … now started rewriting all bootp files with the yealing provisioning generator … maybe that will solve the problem…

lgaetz · July 27, 2018, 7:26pm

Check your firewall and intrusion detection. Sounds like you are triggering a ban.

arhi · July 27, 2018, 7:38pm

that was my original assumption but iptables properly shows that interface is open … I have eth1 on the wan and eth2 on the lan, all sip clients (phones) are on eth2, they don’t see internet at all and that interface is whitelisted … the communication between freepbx and sip phones is open, problem is that content of that communication is weird

cynjut · July 30, 2018, 1:16pm

I thought about this as I was driving across Nebraska this weekend. It almost sounds like you’re having IP address conflicts on the phone LAN. Tell us more about this LAN and tell us about the network support services (DHCP, routing, firewalls, NAT setup, VPN, you know - the usual).

It doesn’t sound like a PBX thing to me unless you’re running out of resources on the box. It sounds like a network issue.

arhi · July 30, 2018, 7:39pm

it’s a lan setup, bunch of 24 port manageable switches, dhcpd and bootp on the server where freepbx is, rather simple setup that works for few years already

ddns-update-style interim;
ignore client-updates;

# Define Custom Options
option option-150 code 150 = ip-address;
option option-120 code 120 = ip-address;
option option-128 code 128 = string;
option option-66  code 66  = ip-address;
option option-43  code 43  = ip-address;


subnet 192.168.1.0 netmask 255.255.255.0 {
        option subnet-mask              255.255.255.0;
        option broadcast-address        192.168.1.255;
        option routers                  192.168.1.10;           # Default Gateway //192.168.1.20 je wifigw
        option time-offset              -18000;                 # Eastern Standard Time

        option domain-name-servers      192.168.1.10;
        option nntp-server              192.168.1.10;
        option option-150               192.168.1.10;           # TFTP Custom Option
        option option-120               192.168.1.10;           # TFTP Custom Option
        option option-66                192.168.1.10;           # TFTP Custom Option
        option option-43                192.168.1.10;           # TFTP Custom Option
        option tftp-server-name         "192.168.1.10";         # TFTP Address
        next-server                     192.168.1.10;           # TFTP Boot
        option option-128               "tftp://192.168.1.10/"; # yealink


        range dynamic-bootp 192.168.1.60 192.168.1.250;

}

arhi · July 30, 2018, 7:40pm

well cpu and io usage is very low, and the phones themselves answer with “error” not the server

BlazeStudios · July 31, 2018, 11:45am

So you don’t see the phones in question actually hit the PBX? And what error do they display when this happens?

gbaughma · August 7, 2018, 3:53pm

What is the topology? “old school” networking says not more than 3 hops… you could be having latency issues if you are going switch to switch to switch.

johnjces · August 8, 2018, 2:20am

Ya know, this is a long shot as such shouldn’t happen but it did to me on two occasions a long time ago. Look for duplicate MAC address in LAN cards, phones and etc.

dicko · August 8, 2018, 2:38am

Duplicate MAC addresses ? that’s a new one, true you can override a mac address on your LAN cards, but you should certainly remember doing it as it takes quite some effort. I would look for a DHCP offered range that is only 100 long. That would be in your DHCP server config.

arhi · August 8, 2018, 7:11am

nothing too complicated, bunch of managed 24port gbit switches, one on the top where the freepbx is connected to and 20 ones connected to that ones with phones connected to them directly …

arhi · August 8, 2018, 7:12am

all phones are cisco and yealink lan is intel, they are in different regions of the 6 byte space so no duplicates between them, phones are provisioned via mac so I’d know if there are duplicates

arhi · August 8, 2018, 7:17am

that initially was a problem, originally I had a range that’s only 100 long and new phones didn’t get the IP at all so could not register, but that one I found inside 5 minutes after adding new phones and changed the dhcpd settings increasing the range… phones do get proper IP, properly register to the freepbx but fail to work properly…

arhi · August 8, 2018, 7:20am

looks like I solved the problem by changing the provisioning file format on all phones… no idea why this works now and did not work earlier and why it stopped working after 98 phones … but I had provisioning template from yealink (huge file with all possible settings) in where I was just changing username/password for each new phone … and it worked up to 98 phones… and stopped … now when I used some yealink “generator” it generates files with only few lines (only user/pass/server:port ) and now it seems to be working ok… it makes zero sense, 90 phones (8 are cisco) with same firmware worked ok with provisioning profile I used and then stopped working after I added 10 new phones… using a “shorter” provisioning profile solves the problem… might be that the main provisioning profile had default setup for 8 lines and while some of the phones do have 8 lines some have only 2 or even only 1 so the additional configured “lines” introduced the problem, but not sure how it used to work for first 90 ?!

dicko · August 8, 2018, 7:44am

when you nmap (the endpoint manager does that) , your network for phones, you need a one to one map of ethernet mac address to ip,.

I think after a scrww up like that i would suggest you delete all your config files and start over

arhi · August 8, 2018, 8:30am

I assume n is here a mistake? (I did use nmap to check what ports where are open but it has nothing to do with endpoint manager)

well I use dhcp to provide ip’s, arp keep track of mac to ip mapping nothing important here just normal networking ?!

and I have mac to user/pass mapping done in the config files.

the only difference is I don’t use endpoint manager, I create extensions trough freepbx gui and I create provisioning config files manually

what scrww-up ? what did I do wrong? I had 98 phones working flawlesly added in number of batches identical every time… last batch failed to work for no reason anyone here can explain so … where’s the error?

system · August 8, 2019, 8:30am

This topic was automatically closed 365 days after the last reply. New replies are no longer allowed.