Engaged signal issue

mrbios · October 11, 2016, 9:25am

Hi,

I’ve got two identical Sangoma S500 phones, both running the same firmware, and all settings are identical (bar the obvious).

When one phone rings another extension/phone that’s in use, they get an engaged signal (The boop, boop, boop noise).

When the other phone rings an in use extension they get no engaged signal, instead they the phone has 1 second of silence then returns the user to the main screen of the phone with no indication of what’s wrong.

Both were tested with dialling the same phone/extension, so it must be the other end that the issue is occurring. Still quite new to this so no idea where to look for this issue! EDIT: I should clarify that the issue is the one that doesn’t get the engaged signal

mrbios · October 20, 2016, 10:47am

Got round to looking at this again…
Any extension with a voicemailbox is getting a “The person is currently on the phone, please leave a message” but anyone without a mailbox is just cutting off instantly rather than getting an engaged signal.

Any suggestions based on that extra information?

EDIT: Additionall, call waiting features are turned off on the phones. We don’t use call waiting, we just want an engaged signal.

cynjut · October 20, 2016, 2:20pm

Have you looked at the Optional Destination settings at the bottom of the “Advanced” tab.

lgaetz · October 20, 2016, 2:35pm

I suspect that the “Remote Disconnect” in the Template Options tab in EPM for each phone is set to something different.

mrbios · October 20, 2016, 2:44pm

@cynjut I’ve played around with this, if i set it to terminal at permanent hold, or the SITS tone, or to ring they work fine. However if i set it to terminate at busy or congested signal it just does the same thing as above.

@lgaetz I’ve tried it with both phones with remote disconnect set to on and off, no change unfortunately.

cynjut · October 20, 2016, 3:02pm

Check your log at /var/log/asterisk/full and see if you are getting an error. I suspect you are getting a codec error on the “busy tone” sound file.

mrbios · October 21, 2016, 7:03am

This is what I’m seeing in the log when trying to call and it cuts off:
– Executing [583@from-internal:1] GotoIf(“PJSIP/507-00000a02”, “1?ext-local,583,1:followme-check,583,1”) in new stack
– Goto (ext-local,583,1)
– Executing [583@ext-local:1] Set(“PJSIP/507-00000a02”, “__RINGTIMER=15”) in new stack
– Executing [583@ext-local:2] Macro(“PJSIP/507-00000a02”, “exten-vm,novm,583,0,1,0”) in new stack
– Executing [s@macro-exten-vm:1] Macro(“PJSIP/507-00000a02”, “user-callerid,”) in new stack
– Executing [s@macro-user-callerid:1] Set(“PJSIP/507-00000a02”, “TOUCH_MONITOR=1477033356.2891”) in new stack
– Executing [s@macro-user-callerid:2] Set(“PJSIP/507-00000a02”, “AMPUSER=507”) in new stack
– Executing [s@macro-user-callerid:3] GotoIf(“PJSIP/507-00000a02”, “0?report”) in new stack
– Executing [s@macro-user-callerid:4] ExecIf(“PJSIP/507-00000a02”, “1?Set(REALCALLERIDNUM=507)”) in new stack
– Executing [s@macro-user-callerid:5] Set(“PJSIP/507-00000a02”, “AMPUSER=507”) in new stack
– Executing [s@macro-user-callerid:6] GotoIf(“PJSIP/507-00000a02”, “0?limit”) in new stack
– Executing [s@macro-user-callerid:7] Set(“PJSIP/507-00000a02”, “AMPUSERCIDNAME=James”) in new stack
– Executing [s@macro-user-callerid:8] GotoIf(“PJSIP/507-00000a02”, “0?report”) in new stack
– Executing [s@macro-user-callerid:9] Set(“PJSIP/507-00000a02”, “AMPUSERCID=507”) in new stack
– Executing [s@macro-user-callerid:10] Set(“PJSIP/507-00000a02”, “__DIAL_OPTIONS=Ttr”) in new stack
– Executing [s@macro-user-callerid:11] Set(“PJSIP/507-00000a02”, “CALLERID(all)=“James” <507>”) in new stack
– Executing [s@macro-user-callerid:12] GotoIf(“PJSIP/507-00000a02”, “0?limit”) in new stack
– Executing [s@macro-user-callerid:13] ExecIf(“PJSIP/507-00000a02”, “0?Set(GROUP(concurrency_limit)=507)”) in new stack
– Executing [s@macro-user-callerid:14] ExecIf(“PJSIP/507-00000a02”, “1?Set(CHANNEL(language)=en)”) in new stack
– Executing [s@macro-user-callerid:15] GotoIf(“PJSIP/507-00000a02”, “0?continue”) in new stack
– Executing [s@macro-user-callerid:16] ExecIf(“PJSIP/507-00000a02”, “1?Set(__CALLEE_ACCOUNCODE=)”) in new stack
– Executing [s@macro-user-callerid:17] Set(“PJSIP/507-00000a02”, “__TTL=64”) in new stack
– Executing [s@macro-user-callerid:18] GotoIf(“PJSIP/507-00000a02”, “1?continue”) in new stack
– Goto (macro-user-callerid,s,29)
– Executing [s@macro-user-callerid:29] Set(“PJSIP/507-00000a02”, “CALLERID(number)=507”) in new stack
– Executing [s@macro-user-callerid:30] Set(“PJSIP/507-00000a02”, “CALLERID(name)=James”) in new stack
– Executing [s@macro-user-callerid:31] GotoIf(“PJSIP/507-00000a02”, “0?cnum”) in new stack
– Executing [s@macro-user-callerid:32] Set(“PJSIP/507-00000a02”, “CDR(cnam)=James”) in new stack
– Executing [s@macro-user-callerid:33] Set(“PJSIP/507-00000a02”, “CDR(cnum)=507”) in new stack
– Executing [s@macro-user-callerid:34] Set(“PJSIP/507-00000a02”, “CHANNEL(language)=en”) in new stack
– Executing [s@macro-exten-vm:2] Set(“PJSIP/507-00000a02”, “RingGroupMethod=none”) in new stack
– Executing [s@macro-exten-vm:3] Set(“PJSIP/507-00000a02”, “__EXTTOCALL=583”) in new stack
– Executing [s@macro-exten-vm:4] Set(“PJSIP/507-00000a02”, “__PICKUPMARK=583”) in new stack
– Executing [s@macro-exten-vm:5] Set(“PJSIP/507-00000a02”, “RT=15”) in new stack
– Executing [s@macro-exten-vm:6] ExecIf(“PJSIP/507-00000a02”, “0?Macro(vm,novm,DIRECTDIAL,)”) in new stack
– Executing [s@macro-exten-vm:7] ExecIf(“PJSIP/507-00000a02”, “0?MacroExit()”) in new stack
– Executing [s@macro-exten-vm:8] Gosub(“PJSIP/507-00000a02”, “sub-record-check,s,1(exten,583,dontcare)”) in new stack
– Executing [s@sub-record-check:1] GotoIf(“PJSIP/507-00000a02”, “0?initialized”) in new stack
– Executing [s@sub-record-check:2] Set(“PJSIP/507-00000a02”, “__REC_STATUS=INITIALIZED”) in new stack
– Executing [s@sub-record-check:3] Set(“PJSIP/507-00000a02”, “NOW=1477033356”) in new stack
– Executing [s@sub-record-check:4] Set(“PJSIP/507-00000a02”, “__DAY=21”) in new stack
– Executing [s@sub-record-check:5] Set(“PJSIP/507-00000a02”, “__MONTH=10”) in new stack
– Executing [s@sub-record-check:6] Set(“PJSIP/507-00000a02”, “__YEAR=2016”) in new stack
– Executing [s@sub-record-check:7] Set(“PJSIP/507-00000a02”, “__TIMESTR=20161021-080236”) in new stack
– Executing [s@sub-record-check:8] Set(“PJSIP/507-00000a02”, “__FROMEXTEN=507”) in new stack
– Executing [s@sub-record-check:9] Set(“PJSIP/507-00000a02”, “__MON_FMT=wav”) in new stack
– Executing [s@sub-record-check:10] NoOp(“PJSIP/507-00000a02”, “Recordings initialized”) in new stack
– Executing [s@sub-record-check:11] ExecIf(“PJSIP/507-00000a02”, “0?Set(ARG3=dontcare)”) in new stack
– Executing [s@sub-record-check:12] Set(“PJSIP/507-00000a02”, “REC_POLICY_MODE_SAVE=”) in new stack
– Executing [s@sub-record-check:13] ExecIf(“PJSIP/507-00000a02”, “0?Set(REC_STATUS=NO)”) in new stack
– Executing [s@sub-record-check:14] GotoIf(“PJSIP/507-00000a02”, “5?checkaction”) in new stack
– Goto (sub-record-check,s,17)
– Executing [s@sub-record-check:17] GotoIf(“PJSIP/507-00000a02”, “1?sub-record-check,exten,1”) in new stack
– Goto (sub-record-check,exten,1)
– Executing [exten@sub-record-check:1] NoOp(“PJSIP/507-00000a02”, “Exten Recording Check between 507 and 583”) in new stack
– Executing [exten@sub-record-check:2] Set(“PJSIP/507-00000a02”, “CALLTYPE=internal”) in new stack
– Executing [exten@sub-record-check:3] ExecIf(“PJSIP/507-00000a02”, “0?Set(CALLTYPE=)”) in new stack
– Executing [exten@sub-record-check:4] Set(“PJSIP/507-00000a02”, “CALLEE=dontcare”) in new stack
– Executing [exten@sub-record-check:5] ExecIf(“PJSIP/507-00000a02”, “0?Set(CALLEE=dontcare)”) in new stack
– Executing [exten@sub-record-check:6] GotoIf(“PJSIP/507-00000a02”, “0?callee”) in new stack
– Executing [exten@sub-record-check:7] GotoIf(“PJSIP/507-00000a02”, “1?caller”) in new stack
– Goto (sub-record-check,exten,13)
– Executing [exten@sub-record-check:13] Set(“PJSIP/507-00000a02”, “RECMODE=dontcare”) in new stack
– Executing [exten@sub-record-check:14] ExecIf(“PJSIP/507-00000a02”, “0?Set(RECMODE=dontcare)”) in new stack
– Executing [exten@sub-record-check:15] ExecIf(“PJSIP/507-00000a02”, “1?Set(RECMODE=dontcare)”) in new stack
– Executing [exten@sub-record-check:16] Gosub(“PJSIP/507-00000a02”, “recordcheck,1(dontcare,internal,583)”) in new stack
– Executing [recordcheck@sub-record-check:1] NoOp(“PJSIP/507-00000a02”, “Starting recording check against dontcare”) in new stack
– Executing [recordcheck@sub-record-check:2] Goto(“PJSIP/507-00000a02”, “dontcare”) in new stack
– Goto (sub-record-check,recordcheck,3)
– Executing [recordcheck@sub-record-check:3] Return(“PJSIP/507-00000a02”, “”) in new stack
– Executing [exten@sub-record-check:17] Return(“PJSIP/507-00000a02”, “”) in new stack
– Executing [s@macro-exten-vm:9] GotoIf(“PJSIP/507-00000a02”, “1?macrodial”) in new stack
– Goto (macro-exten-vm,s,15)
– Executing [s@macro-exten-vm:15] GosubIf(“PJSIP/507-00000a02”, “0?clrheader,1()”) in new stack
– Executing [s@macro-exten-vm:16] Macro(“PJSIP/507-00000a02”, “dial-one,15,Ttr,583”) in new stack
– Executing [s@macro-dial-one:1] Set(“PJSIP/507-00000a02”, “DEXTEN=583”) in new stack
– Executing [s@macro-dial-one:2] Set(“PJSIP/507-00000a02”, “DIALSTATUS_CW=”) in new stack
– Executing [s@macro-dial-one:3] GosubIf(“PJSIP/507-00000a02”, “0?screen,1()”) in new stack
– Executing [s@macro-dial-one:4] GosubIf(“PJSIP/507-00000a02”, “0?cf,1()”) in new stack
– Executing [s@macro-dial-one:5] GotoIf(“PJSIP/507-00000a02”, “1?skip1”) in new stack
– Goto (macro-dial-one,s,8)
– Executing [s@macro-dial-one:8] GotoIf(“PJSIP/507-00000a02”, “0?nodial”) in new stack
– Executing [s@macro-dial-one:9] GotoIf(“PJSIP/507-00000a02”, “0?continue”) in new stack
– Executing [s@macro-dial-one:10] Set(“PJSIP/507-00000a02”, “EXTHASCW=”) in new stack
– Executing [s@macro-dial-one:11] GotoIf(“PJSIP/507-00000a02”, “1?next1:cwinusebusy”) in new stack
– Goto (macro-dial-one,s,12)
– Executing [s@macro-dial-one:12] GotoIf(“PJSIP/507-00000a02”, “0?docfu:skip3”) in new stack
– Goto (macro-dial-one,s,16)
– Executing [s@macro-dial-one:16] GotoIf(“PJSIP/507-00000a02”, “1?next2:continue”) in new stack
– Goto (macro-dial-one,s,17)
– Executing [s@macro-dial-one:17] GotoIf(“PJSIP/507-00000a02”, “0?continue”) in new stack
– Executing [s@macro-dial-one:18] ExecIf(“PJSIP/507-00000a02”, “0?Set(DIALSTATUS=BUSY)”) in new stack
– Executing [s@macro-dial-one:19] GotoIf(“PJSIP/507-00000a02”, “0?cwinusebusy”) in new stack
– Executing [s@macro-dial-one:20] Set(“PJSIP/507-00000a02”, “DEXTEN=”) in new stack
– Executing [s@macro-dial-one:21] Set(“PJSIP/507-00000a02”, “DIALSTATUS=BUSY”) in new stack
– Executing [s@macro-dial-one:22] Goto(“PJSIP/507-00000a02”, “nodial”) in new stack
– Goto (macro-dial-one,s,53)
– Executing [s@macro-dial-one:53] ExecIf(“PJSIP/507-00000a02”, “0?Set(DIALSTATUS=NOANSWER)”) in new stack
– Executing [s@macro-dial-one:54] NoOp(“PJSIP/507-00000a02”, “Returned from dial-one with nothing to call and DIALSTATUS: BUSY”) in new stack
– Executing [s@macro-dial-one:55] MacroExit(“PJSIP/507-00000a02”, “”) in new stack
– Executing [s@macro-exten-vm:17] Set(“PJSIP/507-00000a02”, “SV_DIALSTATUS=BUSY”) in new stack
– Executing [s@macro-exten-vm:18] GosubIf(“PJSIP/507-00000a02”, “0?docfu,1()”) in new stack
– Executing [s@macro-exten-vm:19] GosubIf(“PJSIP/507-00000a02”, “0?docfb,1()”) in new stack
– Executing [s@macro-exten-vm:20] Set(“PJSIP/507-00000a02”, “DIALSTATUS=BUSY”) in new stack
– Executing [s@macro-exten-vm:21] ExecIf(“PJSIP/507-00000a02”, “1?MacroExit()”) in new stack
– Executing [583@ext-local:3] Set(“PJSIP/507-00000a02”, “__PICKUPMARK=”) in new stack
– Executing [583@ext-local:4] GotoIf(“PJSIP/507-00000a02”, “1?app-blackhole,busy,1”) in new stack
– Goto (app-blackhole,busy,1)
– Executing [busy@app-blackhole:1] NoOp(“PJSIP/507-00000a02”, “Blackhole Dest: Busy”) in new stack
– Executing [busy@app-blackhole:2] Progress(“PJSIP/507-00000a02”, “”) in new stack
– Executing [busy@app-blackhole:3] Busy(“PJSIP/507-00000a02”, “20”) in new stack
[2016-10-21 08:02:36] WARNING[9180][C-0000049e]: channel.c:4910 ast_prod: Prodding channel ‘PJSIP/507-00000a02’ failed
== Spawn extension (app-blackhole, busy, 3) exited non-zero on ‘PJSIP/507-00000a02’

mrbios · October 21, 2016, 8:25am

Seems this issue isn’t internal only like i though, if external numbers are engaged (presumably in this case, as they do eventually get through…) we get the same issue.

mrbios · October 21, 2016, 11:45am

Log from the phone (Sangoma S500):
[10-21 12:34:43 50:0f:54] chn=0, AEC_switch = 0
[10-21 12:34:43 50:0f:54] MS: Chn 0 MSDspStopSendRev
[10-21 12:34:43 50:0f:54] CallCtl: SendEvent2Lcm: aid 0, Line: 0, event 0x8dd
[10-21 12:34:43 50:0f:54] CALL: State=0x61, Event=0x127, Chn=0
[10-21 12:34:43 50:0f:54] CallCtl: SendEvent2Lcm: aid 0, Line: 0, event 0x8d7
[10-21 12:34:43 50:0f:54] SIP: sdp_message_pro: Local IP is 172.18.67.21
[10-21 12:34:43 50:0f:54] SIP: SendInvite to 583, cid 437, wIP 0xac124315, port 12100, Interval 2, Codec 0, Audio 0
[10-21 12:34:43 50:0f:54] ReDialInfo: aid 0, line 0, Number 583
[10-21 12:34:43 50:0f:54] CALL: State=0x62, Event=0x201, Chn=0
[10-21 12:34:43 50:0f:54] SIP: aid 0, cid 437, tid 50818, did 0, REQUEST: INVITE, Event: 12
[10-21 12:34:43 50:0f:54] SIP: aid 0, cid 437, tid 50818, did 0, RESPONSE: 401 Unauthorized, 4xx received for Call!, Event: 12
[10-21 12:34:43 50:0f:54] SIP: find_authentication_info, aid 0, username: 507, realm: “asterisk”
[10-21 12:34:43 50:0f:54] SIP: find_auth_info, aid 0, username: 507, account match
[10-21 12:34:43 50:0f:54] SIP: aid 0, cid 437, tid 50819, did 0, REQUEST: INVITE, Event: 8
[10-21 12:34:43 50:0f:54] SIP: aid 0, cid 437, tid 50819, did 0, RESPONSE: 100 Trying, Call is being processed!, Event: 8
[10-21 12:34:43 50:0f:54] GUI: CALL_OFFHOOK, Index:0
[10-21 12:34:43 50:0f:54] GUI: 1:Call LCMSUBCallData:31035360:subdatastatistic:315
[10-21 12:34:43 50:0f:54] SIP: aid 0, cid 437, tid 50819, did 0, REQUEST: INVITE, Event: 12
[10-21 12:34:43 50:0f:54] SIP: aid 0, cid 437, tid 50819, did 0, RESPONSE: 486 Busy Here, 4xx received for Call!, Event: 12
[10-21 12:34:43 50:0f:54] SIP: ActionUrlCall, can’t get call_dialog!!!
[10-21 12:34:43 50:0f:54] SIP: ActionUrlPro active_url sip:[email protected]:5060
[10-21 12:34:43 50:0f:54] SIP: Send CALL_FAILURE (486 Busy Here) to LCM
[10-21 12:34:43 50:0f:54] SIP: aid 0 recv 486, Busy Here
[10-21 12:34:43 50:0f:54] CALL: State=0x62, Event=0x306, Chn=0
[10-21 12:34:43 50:0f:54] XPhoneRelPro:20481######===>>>Line 0 LineState 0x62…
[10-21 12:34:43 50:0f:54] SendSpecialEvent2LCM: Event=2534
[10-21 12:34:43 50:0f:54] CALL: _XPhoneNextState…
[10-21 12:34:43 50:0f:54] CALL: Clear Transfer, Conf and NS Flag
[10-21 12:34:43 50:0f:54] CALL: There isn’t any call, Release
[10-21 12:34:43 50:0f:54] CallCtl: SendEvent2Lcm: aid 0, Line: 0, event 0x8f7
[10-21 12:34:43 50:0f:54] CallCtl: SendEvent2Lcm: aid 0, Line: 0, event 0x954
[10-21 12:34:43 50:0f:54] SendSpecialEvent2LCM: Event=2534
[10-21 12:34:43 50:0f:54] chn=0, AEC_switch = 0
[10-21 12:34:43 50:0f:54] MS: Chn 0 MSDspStopSendRev
[10-21 12:34:43 50:0f:54] CallCtl: SendEvent2Lcm: aid 0, Line: 0, event 0x8e1
[10-21 12:34:43 50:0f:54] LCM: received CALL_FAILURE:2355,reason:Busy Here
[10-21 12:34:43 50:0f:54] GUI: CALL_OFFHOOKTYPE:1
[10-21 12:34:43 50:0f:54] GUI: CALL_OUTGOING, Index:0
[10-21 12:34:43 50:0f:54] GUI: MSG_PAINT
[10-21 12:34:43 50:0f:54] L2Call receive NormalReleaseEvent, release
[10-21 12:34:43 50:0f:54] SIPPro: 12811, Release All Sip Dialog!!
[10-21 12:34:43 50:0f:54] CALL: State=0x60, Event=0x91c, Chn=0
[10-21 12:34:43 50:0f:54] CALL: LCM Exit MenuCfg
[10-21 12:34:43 50:0f:54] GUI: num:0,HLGUIData.ScrewView.ScrewItemNum:0
[10-21 12:34:43 50:0f:54] GUI: CALL_FAILURE, Account:0
[10-21 12:34:43 50:0f:54] GUI:MS_ZRTP_END_EVENT
[10-21 12:34:43 50:0f:54] GUI: CALL_REL_ALL, Index:0
[10-21 12:34:43 50:0f:54] GUI: 2:Call LCMSUBCallData:31324544:subdatastatistic:316
[10-21 12:34:43 50:0f:54] GUI: Receive CALL_BUSY_UNLOCK_KEYPAD!
[10-21 12:34:43 50:0f:54] GUI:MS_ZRTP_END_EVENT
[10-21 12:34:43 50:0f:54] GUI: CALL_ONHOOK,index:0
[10-21 12:34:43 50:0f:54] GUI: CALL_ONHOOK, Index:0
[10-21 12:34:44 50:0f:54] CALL: State=0x60, Event=0x91c, Chn=0

Does this look more like a phone issue rather than a freepbx issue per chance? I don’t really understand what I’m looking at, but something doesn’t look right with that log…

mrbios · October 27, 2016, 10:11am

Still unable to resolve this.

I’ve recatagorized this under “Sangoma Phones” as i’ve borrowed a yealink phone from someone else and i get the “busy here” tone as one would expect. On the Sangoma phones S300 and S500 (now running the latest 1.22 firmware) I get nothing.

Any suggestions on this new info?

tonyclewis · October 27, 2016, 12:51pm

Ita a firmware issue that we are working on. A bug for introduced when fixing something else. If you go back to firmware .16 you will get busy tone played. It will be fixed in next .19 firmware.

mrbios · October 27, 2016, 12:55pm

Huzzah! Thank you I thought i was going mad.

mrbios · November 23, 2016, 9:36pm

Hi,

I see that the .19 firmware release notes are up on the wiki. However endpoint manager isn’t picking up a 1.23 version is there a way to force endpoint manager to check for an update?

Thanks

EDIT: Ah i found where it comes from, and it appears:
http://ct.schmoozecom.net/sangoma.1.22.tar.gz < works
http://ct.schmoozecom.net/sangoma.1.23.tar.gz < doesn’t exist

Does someone on the endpoint manager end need to upload the new version to that store?

tonyclewis · November 24, 2016, 12:45am

We have not pushed it to EPm yet. We always wait a week or two to let users manually test the firmware.

mrbios · November 24, 2016, 9:59am

Ah thanks, i’ll bare that in mind in the future.