Hi guys!
I need your help again, cannot figure this out on my own.
The system 16.0.39 with all latest patches.
There is only one extension that behaves like this. When dialed from outside or inside it throws a message “The person at extension 100 is on the phone”. Well, that person is not on the phone and claims no DND or status has changed.
The phone is P315, and it deployed via end point manager.
This is 2nd time it is happening, last time it was fixed after phone was rebooted.
Here is an asterisk log during my inbound call to it:
**5522 [2023-03-23 11:29:35] VERBOSE[34629][C-00000018] pbx.c: Executing [vmx@macro-vm:16] GotoIf("SIP/voipms-00000015", "1?s-BUSY,1") in new stack**
**5523 [2023-03-23 11:29:35] VERBOSE[34629][C-00000018] pbx_builtins.c: Goto (macro-vm,s-BUSY,1)**
**5524 [2023-03-23 11:29:35] VERBOSE[34629][C-00000018] pbx.c: Executing [s-BUSY@macro-vm:1] NoOp("SIP/voipms-00000015", "BUSY voicemail") in new stack**
**5525 [2023-03-23 11:29:35] VERBOSE[34629][C-00000018] pbx.c: Executing [s-BUSY@macro-vm:2] Macro("SIP/voipms-00000015", "get-vmcontext,100") in new stack**
**5526 [2023-03-23 11:29:35] VERBOSE[34629][C-00000018] pbx.c: Executing [s@macro-get-vmcontext:1] Set("SIP/voipms-00000015", "VMCONTEXT=default") in new stack**
**5527 [2023-03-23 11:29:35] VERBOSE[34629][C-00000018] pbx.c: Executing [s@macro-get-vmcontext:2] GotoIf("SIP/voipms-00000015", "0?200:300") in new stack**
**5528 [2023-03-23 11:29:35] VERBOSE[34629][C-00000018] pbx_builtins.c: Goto (macro-get-vmcontext,s,300)**
**5529 [2023-03-23 11:29:35] VERBOSE[34629][C-00000018] pbx.c: Executing [s@macro-get-vmcontext:300] NoOp("SIP/voipms-00000015", "") in new stack**
**5530 [2023-03-23 11:29:35] VERBOSE[34629][C-00000018] pbx.c: Executing [s-BUSY@macro-vm:3] VoiceMail("SIP/voipms-00000015", "100@default,b") in new stack**
**5531 [2023-03-23 11:29:35] VERBOSE[34629][C-00000018] file.c: <SIP/voipms-00000015> Playing 'vm-theperson.ulaw' (language 'en')**
**5532 [2023-03-23 11:29:37] VERBOSE[34629][C-00000018] file.c: <SIP/voipms-00000015> Playing 'digits/1.ulaw' (language 'en')**
**5533 [2023-03-23 11:29:38] VERBOSE[34629][C-00000018] file.c: <SIP/voipms-00000015> Playing 'digits/0.ulaw' (language 'en')**
**5534 [2023-03-23 11:29:39] VERBOSE[34629][C-00000018] file.c: <SIP/voipms-00000015> Playing 'digits/0.ulaw' (language 'en')**
**5535 [2023-03-23 11:29:39] VERBOSE[34629][C-00000018] file.c: <SIP/voipms-00000015> Playing 'vm-isonphone.ulaw' (language 'en')**
**5536 [2023-03-23 11:29:41] VERBOSE[34629][C-00000018] file.c: <SIP/voipms-00000015> Playing 'vm-intro.ulaw' (language 'en')**
**5537 [2023-03-23 11:29:47] VERBOSE[34629][C-00000018] file.c: <SIP/voipms-00000015> Playing 'beep.ulaw' (language 'en')**
**5538 [2023-03-23 11:29:47] VERBOSE[34629][C-00000018] app_voicemail.c: Recording the message**
**5539 [2023-03-23 11:29:47] VERBOSE[34629][C-00000018] app.c: x=0, open writing: /var/spool/asterisk/voicemail/default/100/tmp/jOnC6V format: wav, 0x7fdb54042f00**
**5540 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] app.c: User hung up**
**5541 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] app_voicemail.c: Recording was 0 seconds long but needs to be at least 1 - abandoning**
**5542 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] app_macro.c: Spawn extension (macro-vm, s-BUSY, 3) exited non-zero on 'SIP/voipms-00000015' in macro 'vm'**
**5543 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] app_macro.c: Spawn extension (macro-exten-vm, s, 33) exited non-zero on 'SIP/voipms-00000015' in macro 'exten-vm'**
**5544 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Spawn extension (ext-local, 100, 3) exited non-zero on 'SIP/voipms-00000015'**
**5545 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [h@ext-local:1] Macro("SIP/voipms-00000015", "hangupcall,") in new stack**
**5546 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@macro-hangupcall:1] Gosub("SIP/voipms-00000015", "app-missedcall-hangup,s,1()") in new stack**
**5547 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@app-missedcall-hangup:1] NoOp("SIP/voipms-00000015", "Callee: s") in new stack**
**5548 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@app-missedcall-hangup:2] NoOp("SIP/voipms-00000015", "Caller: ") in new stack**
**5549 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@app-missedcall-hangup:3] AGI("SIP/voipms-00000015", "agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,") in new stack**
**5550 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: ********* Missed Call Summary ***********
**5551 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Orginator channel : SIP/voipms-00000015**
**5552 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: unanswered:**
**5553 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Linked Channel ID: 1679596162.44**
**5554 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Unique Channel ID: 1679596162.44**
**5555 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Calling extension: my CID**
**5556 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Calling ext name: my town, CA**
**5557 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Ringing extension: 100**
**5558 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Missed Call UID: 2b4c5818e2cf25db5f37e638078b4b7d**
**5559 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Notification enabled?: 1**
**5560 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Is Internal call?: No**
**5561 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Send Internal Notification?: Yes**
**5562 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Is External call?: Yes**
**5563 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Send External Notification?: Yes**
**5564 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Is Ring Group call?: No**
**5565 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Send Ring Group Notification?: Yes**
**5566 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Is Queue call?: No**
**5567 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Send Queue Notification?: No**
**5568 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: To email: [email protected]**
**5569 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: From email:**
**5570 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: From name:**
**5571 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: agi://127.0.0.1/missedcallnotify.php,100,,s,0,,SIP/voipms-00000015,BUSY,: Uniqueid and Linkedid Processing uniqueid = 1679596162.44**
**5572 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] res_agi.c: <SIP/voipms-00000015>AGI Script agi://127.0.0.1/missedcallnotify.php completed, returning 0**
**5573 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@app-missedcall-hangup:4] Return("SIP/voipms-00000015", "") in new stack**
**5574 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@macro-hangupcall:2] GotoIf("SIP/voipms-00000015", "1?theend") in new stack**
**5575 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx_builtins.c: Goto (macro-hangupcall,s,4)**
**5576 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@macro-hangupcall:4] ExecIf("SIP/voipms-00000015", "0?Set(CDR(recordingfile)=)") in new stack**
**5577 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@macro-hangupcall:5] Hangup("SIP/voipms-00000015", "") in new stack**
**5578 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] app_macro.c: Spawn extension (macro-hangupcall, s, 5) exited non-zero on 'SIP/voipms-00000015' in macro 'hangupcall'**
**5579 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/voipms-00000015'**
**5580 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] app_stack.c: SIP/voipms-00000015 Internal Gosub(crm-hangup,s,1) start**
**5581 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@crm-hangup:1] NoOp("SIP/voipms-00000015", "Sending Hangup to CRM") in new stack**
**5582 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@crm-hangup:2] NoOp("SIP/voipms-00000015", "HANGUP CAUSE: 17") in new stack**
**5583 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@crm-hangup:3] ExecIf("SIP/voipms-00000015", "1?Set(__CRM_VOICEMAIL=FAILED)") in new stack**
**5584 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@crm-hangup:4] NoOp("SIP/voipms-00000015", "MASTER CHANNEL: 1679596162.44 = 1679596162.44") in new stack**
**5585 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@crm-hangup:5] GotoIf("SIP/voipms-00000015", "0?return") in new stack**
**5586 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@crm-hangup:6] Set("SIP/voipms-00000015", "__CRM_HANGUP=1") in new stack**
**5587 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [s@crm-hangup:7] AGI("SIP/voipms-00000015", "agi://127.0.0.1/sangomacrm.agi") in new stack**
**5588 [2023-03-23 11:29:49] VERBOSE[34629][C-00000018] res_agi.c: <SIP/voipms-00000015>AGI Script agi://127.0.0.1/sangomacrm.agi completed, returning 0**
**5589 [2023-03-23 11:29:49] VERBOSE[34629][C-00000018] pbx.c: Executing [s@crm-hangup:8] Return("SIP/voipms-00000015", "") in new stack**
**5590 [2023-03-23 11:29:49] VERBOSE[34629][C-00000018] app_stack.c: Spawn extension (ext-local, h, 1) exited non-zero on 'SIP/voipms-00000015'**
**5591 [2023-03-23 11:29:49] VERBOSE[34629][C-00000018] app_stack.c: SIP/voipms-00000015 Internal Gosub(crm-hangup,s,1) complete GOSUB_RETVAL=**
If you could suggest where I should I look to mitigate this issue!
Thanks.