The person at extension XXX is on the phone - on extension which is not

General Help
1

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 [[email protected]: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 [[email protected]:1] NoOp("SIP/voipms-00000015", "BUSY voicemail") in new stack**
**5525 [2023-03-23 11:29:35] VERBOSE[34629][C-00000018] pbx.c: Executing [[email protected]: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 [[email protected]:1] Set("SIP/voipms-00000015", "VMCONTEXT=default") in new stack**
**5527 [2023-03-23 11:29:35] VERBOSE[34629][C-00000018] pbx.c: Executing [[email protected]: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 [[email protected]:300] NoOp("SIP/voipms-00000015", "") in new stack**
**5530 [2023-03-23 11:29:35] VERBOSE[34629][C-00000018] pbx.c: Executing [[email protected]:3] VoiceMail("SIP/voipms-00000015", "[email protected],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 [[email protected]:1] Macro("SIP/voipms-00000015", "hangupcall,") in new stack**
**5546 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [[email protected]: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 [[email protected]:1] NoOp("SIP/voipms-00000015", "Callee: s") in new stack**
**5548 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [[email protected]:2] NoOp("SIP/voipms-00000015", "Caller: ") in new stack**
**5549 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [[email protected]: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 [[email protected]:4] Return("SIP/voipms-00000015", "") in new stack**
**5574 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:5] GotoIf("SIP/voipms-00000015", "0?return") in new stack**
**5586 [2023-03-23 11:29:48] VERBOSE[34629][C-00000018] pbx.c: Executing [[email protected]: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 [[email protected]: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 [[email protected]: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.

2

Your log already starts at noting that asterisk thinks the Extension is busy.

Are you using pjsip for these phones? If you do pjsip show contacts how does it list the extension?

Is call waiting on the extension disabled?

3

Seems like call waiting is enabled for all extensions, should I disable it?

All extensions are pjsip via UDP.

Where do I run that syntax (pjsip show contacts) in asterisk vvvr?

4

here is what I observe after that command:

image
image1328×301 22.8 KB

5

ext. 100 is one affected by this. I disabled call waiting for it but no changes.

6

You want CW enabled not disabled. Sorry I wasn’t clear.

For some reason asterisk thinks the extension is busy and it’s sending the call to VM.

I think you’ll need to provide a call log that starts much sooner then what you’ve provided here in your initial post.

7

Ok, I’ll try to capture more.

8

Here is my log at pastebin

9

So, user was mad about this and I cycled port on the switch and it works now.

How do I prevent this from happening??? :man_facepalming:

10

You need to provide a log starting before the call fails, preferably the whole call. Your log starts after the point of failure.

[ Looks like I didn’t see the pastebin version of the log ]

11

Ok, I thought I did, I copied entire block as soon put asterisk -vvvr and dialed their DID.

I will try again but now it works as it should. Do I need to set pjsip logger once inside of asterisk debug console?

12

If it’s the phone responding to asterisk that it’s busy when it’s not it might be a phone firmware issue. When you bounced the port would that have bounced the PoE and restarted the phone?

Might want to look at simply updating firmware on the phone if it’s not at the latest firmware.

13

Yes, it’s PoE port on Cisco L3 switch.

Sadly if you login to its web-page it won’t allow to fiddle with settings. Although EPM has latest firmware release.

I suspect this particular phone was one I played with on my own PBX by configuring with my EPM. Is it possible it has some remnants in config file that can cause this?

14

I notice this contains a URI parameter (;ob) I haven’t seen before, on the contact URI, presumably taken from the registration. This appears to be taken from RFC 5626. At the moment I can’t work out if it being used correctly.

The examples in the RFC do not contain ;ob in its example registration Contact headers, or in any request URIs, but it is heavy reading and I can’t be certain that they aren’t allowed. Unfortunately, the RFC lacks the normal table showing in exactly which request types options are allowed.

I’d quite like to see whether the REGISTER or its response contained Supported: outbound or Require: outbound.

I notice the code has gone into the missed call path, but the log has no timestamps, which normally means it was taken from the console screen, rather the proper log file. Without the timestamps, I can’t tell if it failed quickly, so probably wasn’t a true missed call, as defined, recently, in the forum, or it really was an unanswered call.

15

I’m wondering if this is yet another SIP ALG (application level gateway) problem in a router - the router may be adding ;ob when it shouldn’t. The RFC seems to have completely different special parameters on REGISTER Contact URIs.

16

Hi David,

Are you referring to the device that does routing for that network? I don’t see that option on the switch.
This only happens to 1 device to my knowledge.

17

SIP ALG is something you find on routers. I think the intention is to ease NAT problems, but it seems almost universal experience that they make things worse. It may go under other names. Basically, you do not want routers to look at the details of SIP traffic.

18

Hmm, it’s a switch who handles all internal traffic due to huge spread. NAT comes in into a play to access from outside, wonder if Cisco has something on the switch side for this. I also prioritize SIP traffic on that LAN.
But why this happens only with single extension/phone?

19

I think I’d want a full packet capture for both Asterisk and locally to the phone, in including the responses. If a router/switch is adding ;ob, and not removing it on the return path, some phones may not like the change in the request URI.

Cisco wrote the RFC in question, so it is naughty if they are not following it, but Cisco also has a reputation for not working well with Asterisk.

20

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