Extensions are busied out

SteveA · April 14, 2022, 1:30pm

Hi, I have been running 20 extensions via asterisk / FreePbx for many years without issue. In the last 10 days, 3 of these old (chan-sip) extensions, have suddenly become unreachable, either from internal, or incoming via ring groups.

Initially, from debug, I thought that the issue was related to CW not being enabled, and this still may be a factor that I have not yet managed to address.

I then suspected HW config as 2 of the 3 lines are on one phone, however I have discounted that as there are 2 lines on the second phone, one which rings fine, and one which is always busy.

I have noticed that ONLY these 3 extensions exist in the findmefollow table, so I disabled that module, but to no effect.

All extensions are registered and show in sip peers table. All extensions can ring out. I have deleted and recreated the extensions to no effect.

All of these extensions have been running since …

Possibly coincidentally, I have recently upgraded several modules including CORE.

Below is the level 4 for the non ringing extension:

 -- Executing [1004@from-internal:1] Set("SIP/1002-0000000c", "__RINGTIMER=15") in new stack
    -- Executing [1004@from-internal:2] ExecIf("SIP/1002-0000000c", "0?Set(__CWIGNORE=)") in new stack
    -- Executing [1004@from-internal:3] Macro("SIP/1002-0000000c", "exten-vm,novm,1004,0,0,0") in new stack
    -- Executing [s@macro-exten-vm:1] Macro("SIP/1002-0000000c", "user-callerid,") in new stack
    -- Executing [s@macro-user-callerid:1] Set("SIP/1002-0000000c", "TOUCH_MONITOR=1649938457.60") in new stack
    -- Executing [s@macro-user-callerid:2] Set("SIP/1002-0000000c", "CHANCONTEXT=") in new stack
    -- Executing [s@macro-user-callerid:3] Set("SIP/1002-0000000c", "CHANCONTEXT=") in new stack
    -- Executing [s@macro-user-callerid:4] Set("SIP/1002-0000000c", "CHANEXTENCONTEXT=1002-0000000c") in new stack
    -- Executing [s@macro-user-callerid:5] Set("SIP/1002-0000000c", "CHANEXTEN=1002-0000000c") in new stack
    -- Executing [s@macro-user-callerid:6] Set("SIP/1002-0000000c", "CALLERID(number)=1002") in new stack
    -- Executing [s@macro-user-callerid:7] Set("SIP/1002-0000000c", "AMPUSER=1002") in new stack
    -- Executing [s@macro-user-callerid:8] Set("SIP/1002-0000000c", "HOTDESCKCHAN=1002-0000000c") in new stack
    -- Executing [s@macro-user-callerid:9] Set("SIP/1002-0000000c", "HOTDESKEXTEN=1002") in new stack
    -- Executing [s@macro-user-callerid:10] Set("SIP/1002-0000000c", "HOTDESKCALL=0") in new stack
    -- Executing [s@macro-user-callerid:11] ExecIf("SIP/1002-0000000c", "0?Set(HOTDESKCALL=1)") in new stack
    -- Executing [s@macro-user-callerid:12] ExecIf("SIP/1002-0000000c", "0?Set(CALLERID(name)=)") in new stack
    -- Executing [s@macro-user-callerid:13] GotoIf("SIP/1002-0000000c", "0?report") in new stack
    -- Executing [s@macro-user-callerid:14] ExecIf("SIP/1002-0000000c", "1?Set(REALCALLERIDNUM=1002)") in new stack
    -- Executing [s@macro-user-callerid:15] Set("SIP/1002-0000000c", "AMPUSER=") in new stack
    -- Executing [s@macro-user-callerid:16] GotoIf("SIP/1002-0000000c", "0?limit") in new stack
    -- Executing [s@macro-user-callerid:17] Set("SIP/1002-0000000c", "AMPUSERCIDNAME=") in new stack
    -- Executing [s@macro-user-callerid:18] ExecIf("SIP/1002-0000000c", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
    -- Executing [s@macro-user-callerid:19] GotoIf("SIP/1002-0000000c", "1?report") in new stack
    -- Goto (macro-user-callerid,s,28)
    -- Executing [s@macro-user-callerid:28] NoOp("SIP/1002-0000000c", "Macro Depth is 2") in new stack
    -- Executing [s@macro-user-callerid:29] GotoIf("SIP/1002-0000000c", "1?report2:macroerror") in new stack
    -- Goto (macro-user-callerid,s,30)
    -- Executing [s@macro-user-callerid:30] GotoIf("SIP/1002-0000000c", "0?continue") in new stack
    -- Executing [s@macro-user-callerid:31] Set("SIP/1002-0000000c", "__TTL=64") in new stack
    -- Executing [s@macro-user-callerid:32] GotoIf("SIP/1002-0000000c", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,48)
    -- Executing [s@macro-user-callerid:48] Set("SIP/1002-0000000c", "CALLERID(number)=1002") in new stack
    -- Executing [s@macro-user-callerid:49] Set("SIP/1002-0000000c", "CALLERID(name)=1002") in new stack
    -- Executing [s@macro-user-callerid:50] GotoIf("SIP/1002-0000000c", "0?cnum") in new stack
    -- Executing [s@macro-user-callerid:51] Set("SIP/1002-0000000c", "CDR(cnam)=1002") in new stack
    -- Executing [s@macro-user-callerid:52] Set("SIP/1002-0000000c", "CDR(cnum)=1002") in new stack
    -- Executing [s@macro-user-callerid:53] Set("SIP/1002-0000000c", "CHANNEL(language)=fr") in new stack
    -- Executing [s@macro-exten-vm:2] Set("SIP/1002-0000000c", "RingGroupMethod=none") in new stack
    -- Executing [s@macro-exten-vm:3] Set("SIP/1002-0000000c", "__EXTTOCALL=1004") in new stack
    -- Executing [s@macro-exten-vm:4] Set("SIP/1002-0000000c", "__PICKUPMARK=1004") in new stack
    -- Executing [s@macro-exten-vm:5] Set("SIP/1002-0000000c", "RT=") in new stack
    -- Executing [s@macro-exten-vm:6] Gosub("SIP/1002-0000000c", "sub-record-check,s,1(exten,1004,dontcare)") in new stack
    -- Executing [s@sub-record-check:1] GotoIf("SIP/1002-0000000c", "0?initialized") in new stack
    -- Executing [s@sub-record-check:2] Set("SIP/1002-0000000c", "__REC_STATUS=INITIALIZED") in new stack
    -- Executing [s@sub-record-check:3] Set("SIP/1002-0000000c", "NOW=1649938457") in new stack
    -- Executing [s@sub-record-check:4] Set("SIP/1002-0000000c", "__DAY=14") in new stack
    -- Executing [s@sub-record-check:5] Set("SIP/1002-0000000c", "__MONTH=04") in new stack
    -- Executing [s@sub-record-check:6] Set("SIP/1002-0000000c", "__YEAR=2022") in new stack
    -- Executing [s@sub-record-check:7] Set("SIP/1002-0000000c", "__TIMESTR=20220414-141417") in new stack
    -- Executing [s@sub-record-check:8] Set("SIP/1002-0000000c", "__FROMEXTEN=1002") in new stack
    -- Executing [s@sub-record-check:9] Set("SIP/1002-0000000c", "__MON_FMT=wav") in new stack
    -- Executing [s@sub-record-check:10] NoOp("SIP/1002-0000000c", "Recordings initialized") in new stack
    -- Executing [s@sub-record-check:11] ExecIf("SIP/1002-0000000c", "0?Set(ARG3=dontcare)") in new stack
    -- Executing [s@sub-record-check:12] Set("SIP/1002-0000000c", "REC_POLICY_MODE_SAVE=") in new stack
    -- Executing [s@sub-record-check:13] ExecIf("SIP/1002-0000000c", "0?Set(REC_STATUS=NO)") in new stack
    -- Executing [s@sub-record-check:14] GotoIf("SIP/1002-0000000c", "5?checkaction") in new stack
    -- Goto (sub-record-check,s,17)
    -- Executing [s@sub-record-check:17] GotoIf("SIP/1002-0000000c", "1?sub-record-check,exten,1") in new stack
    -- Goto (sub-record-check,exten,1)
    -- Executing [exten@sub-record-check:1] NoOp("SIP/1002-0000000c", "Exten Recording Check between 1002 and 1004") in new stack
    -- Executing [exten@sub-record-check:2] Set("SIP/1002-0000000c", "CALLTYPE=internal") in new stack
    -- Executing [exten@sub-record-check:3] ExecIf("SIP/1002-0000000c", "0?Set(CALLTYPE=)") in new stack
    -- Executing [exten@sub-record-check:4] Set("SIP/1002-0000000c", "CALLEE=") in new stack
    -- Executing [exten@sub-record-check:5] ExecIf("SIP/1002-0000000c", "1?Set(CALLEE=dontcare)") in new stack
    -- Executing [exten@sub-record-check:6] GotoIf("SIP/1002-0000000c", "0?callee") in new stack
    -- Executing [exten@sub-record-check:7] GotoIf("SIP/1002-0000000c", "1?caller") in new stack
    -- Goto (sub-record-check,exten,13)
    -- Executing [exten@sub-record-check:13] Set("SIP/1002-0000000c", "RECMODE=") in new stack
    -- Executing [exten@sub-record-check:14] Set("SIP/1002-0000000c", "CALLERRECMODE=") in new stack
    -- Executing [exten@sub-record-check:15] Set("SIP/1002-0000000c", "CALEERECMODE=") in new stack
    -- Executing [exten@sub-record-check:16] GotoIf("SIP/1002-0000000c", "1?processnormal") in new stack
    -- Goto (sub-record-check,exten,21)
    -- Executing [exten@sub-record-check:21] ExecIf("SIP/1002-0000000c", "1?Set(RECMODE=dontcare)") in new stack
    -- Executing [exten@sub-record-check:22] ExecIf("SIP/1002-0000000c", "1?Set(RECMODE=dontcare)") in new stack
    -- Executing [exten@sub-record-check:23] Gosub("SIP/1002-0000000c", "recordcheck,1(dontcare,internal,1004)") in new stack
    -- Executing [recordcheck@sub-record-check:1] NoOp("SIP/1002-0000000c", "Starting recording check against dontcare") in new stack
    -- Executing [recordcheck@sub-record-check:2] Goto("SIP/1002-0000000c", "dontcare") in new stack
    -- Goto (sub-record-check,recordcheck,3)
    -- Executing [recordcheck@sub-record-check:3] Return("SIP/1002-0000000c", "") in new stack
    -- Executing [exten@sub-record-check:24] Return("SIP/1002-0000000c", "") in new stack
    -- Executing [s@macro-exten-vm:7] GotoIf("SIP/1002-0000000c", "1?macrodial") in new stack
    -- Goto (macro-exten-vm,s,13)
    -- Executing [s@macro-exten-vm:13] GosubIf("SIP/1002-0000000c", "0?clrheader,1()") in new stack
    -- Executing [s@macro-exten-vm:14] Macro("SIP/1002-0000000c", "dial-one,,Ttr,1004") in new stack
    -- Executing [s@macro-dial-one:1] Set("SIP/1002-0000000c", "DEXTEN=1004") in new stack
    -- Executing [s@macro-dial-one:2] ExecIf("SIP/1002-0000000c", "0?Set(__EXTTOCALL=1004)") in new stack
    -- Executing [s@macro-dial-one:3] Set("SIP/1002-0000000c", "DIALSTATUS_CW=") in new stack
    -- Executing [s@macro-dial-one:4] GosubIf("SIP/1002-0000000c", "0?screen,1()") in new stack
    -- Executing [s@macro-dial-one:5] GosubIf("SIP/1002-0000000c", "0?cf,1()") in new stack
    -- Executing [s@macro-dial-one:6] GotoIf("SIP/1002-0000000c", "1?skip1") in new stack
    -- Goto (macro-dial-one,s,9)
    -- Executing [s@macro-dial-one:9] GotoIf("SIP/1002-0000000c", "0?nodial") in new stack
    -- Executing [s@macro-dial-one:10] GotoIf("SIP/1002-0000000c", "0?continue") in new stack
    -- Executing [s@macro-dial-one:11] Set("SIP/1002-0000000c", "EXTHASCW=") in new stack
    -- Executing [s@macro-dial-one:12] GotoIf("SIP/1002-0000000c", "1?next1:cwinusebusy") in new stack
    -- Goto (macro-dial-one,s,13)
    -- Executing [s@macro-dial-one:13] GotoIf("SIP/1002-0000000c", "0?docfu:skip3") in new stack
    -- Goto (macro-dial-one,s,17)
    -- Executing [s@macro-dial-one:17] GotoIf("SIP/1002-0000000c", "1?next2:continue") in new stack
    -- Goto (macro-dial-one,s,18)
    -- Executing [s@macro-dial-one:18] GotoIf("SIP/1002-0000000c", "1?continue") in new stack
    -- Goto (macro-dial-one,s,26)
    -- Executing [s@macro-dial-one:26] GotoIf("SIP/1002-0000000c", "0?nodial") in new stack
    -- Executing [s@macro-dial-one:27] GosubIf("SIP/1002-0000000c", "1?dstring,1():dlocal,1()") in new stack
    -- Executing [dstring@macro-dial-one:1] Set("SIP/1002-0000000c", "DSTRING=") in new stack
    -- Executing [dstring@macro-dial-one:2] Set("SIP/1002-0000000c", "DEVICES=") in new stack
    -- Executing [dstring@macro-dial-one:3] ExecIf("SIP/1002-0000000c", "1?Return()") in new stack
    -- Executing [s@macro-dial-one:28] GotoIf("SIP/1002-0000000c", "1?nodial") in new stack
    -- Goto (macro-dial-one,s,60)
    -- Executing [s@macro-dial-one:60] NoOp("SIP/1002-0000000c", "") in new stack
    -- Executing [s@macro-dial-one:61] ExecIf("SIP/1002-0000000c", "1?Set(DIALSTATUS=NOANSWER)") in new stack
    -- Executing [s@macro-dial-one:62] NoOp("SIP/1002-0000000c", "Returned from dial-one with nothing to call and DIALSTATUS: NOANSWER") in new stack
    -- Executing [s@macro-dial-one:63] MacroExit("SIP/1002-0000000c", "") in new stack
    -- Executing [s@macro-exten-vm:15] Set("SIP/1002-0000000c", "SV_DIALSTATUS=NOANSWER") in new stack
    -- Executing [s@macro-exten-vm:16] GosubIf("SIP/1002-0000000c", "0?docfu,1()") in new stack
    -- Executing [s@macro-exten-vm:17] GosubIf("SIP/1002-0000000c", "0?docfb,1()") in new stack
    -- Executing [s@macro-exten-vm:18] Set("SIP/1002-0000000c", "DIALSTATUS=NOANSWER") in new stack
    -- Executing [s@macro-exten-vm:19] ExecIf("SIP/1002-0000000c", "0?MacroExit()") in new stack
    -- Executing [s@macro-exten-vm:20] GotoIf("SIP/1002-0000000c", "1?s-NOANSWER,1") in new stack
    -- Goto (macro-exten-vm,s-NOANSWER,1)
    -- Executing [s-NOANSWER@macro-exten-vm:1] GotoIf("SIP/1002-0000000c", "0?exit,1") in new stack
    -- Executing [s-NOANSWER@macro-exten-vm:2] PlayTones("SIP/1002-0000000c", "congestion") in new stack
    -- Executing [s-NOANSWER@macro-exten-vm:3] Congestion("SIP/1002-0000000c", "10") in new stack
  == Spawn extension (macro-exten-vm, s-NOANSWER, 3) exited non-zero on 'SIP/1002-0000000c' in macro 'exten-vm'
  == Spawn extension (from-internal, 1004, 3) exited non-zero on 'SIP/1002-0000000c'
    -- Executing [h@from-internal:1] Macro("SIP/1002-0000000c", "hangupcall") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("SIP/1002-0000000c", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Executing [s@macro-hangupcall:3] ExecIf("SIP/1002-0000000c", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s@macro-hangupcall:4] Hangup("SIP/1002-0000000c", "") in new stack
  == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/1002-0000000c' in macro 'hangupcall'
  == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/1002-0000000c'

Any suggestions as how to resolve this would be appreciated.

SteveA · April 16, 2022, 9:47am

For posterity, this was a problem of astdb corruption.

When the dialplan did a lookup for the dialled extension

– Executing [dstring@macro-dial-one:2] Set(“SIP/1002-0000000c”, “DEVICES=”) in new stack

multiple identical results were returned, which the DP interpreted as NUL.

Checking the database ( /var/lib/asterisk/astdb.sqlite3 ) showed that it had grown to a staggering 75Mb over the years yet asterisk cli “database show” resulted in only 7 lines - db corruption!

SOLUTION

Shut down freepbx and asterisk
fwconsole stop

Immediately backup the database (freepbx has cron jobs that will try to restart asterisk)
(cp /var/lib/asterisk/astdb.sqlite3 /var/lib/astdb.sqlite3.backup)

Run an integrity check on the backup file

sqlite3 
.open /var/lib/astdb.sqlite3.backup
PRAGMA integrity_check;

This showed multiple errors ( a healthy db will return OK)
To resolve, clone the database (which will also reindex it)

.clone /var/lib/asterisk/astdb.clone.original

and exit sqlite3
Optionally run an integrity check on the clone
The clone was now only 114k!

Check that asterisk has not restarted, stopping if necessary, and then replace the astdb with the clone.

cp /var/lib/asterisk/astdb.clone.original /var/lib/astdb.sqlite3

Now restart

fwconsole start

and the problem should have gone away, and performance is improved!!

Hope this helps someone

system · April 23, 2022, 9:48am

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