Weird calling behaviour (no sound, no hangup, missing keypresses, ...) on local extension to extension calls

jklin · November 14, 2020, 11:42am

(Hopefully I am including all relevant information below, without adding too many details that are not relevant).

I have installed a fresh new copy of FreePBX 15.0.16.76 in a virtual machine hosted on an ESXi server.
I followed the installation wizard and have also created a number of pjsip extensions to get started.
I then connected to two of these - one using a physical Yealink T46S phone, the other using PhonerLite on my computer. Both locally in the office, no VPN.

However, calling behaves “weird” - not sure how to better describe my confusion. Here is a list of issues I am seeing:

Calling the mailbox from phonerLite (*97 or *98) makes a connection, I can hear the vm-password.ulaw message and type in my password/pin. Sometimes not all digits seem to come through, though. However, when I stay in the voicemail menu e.g. by going to mailbox options, the call appears to be disconnected after a few seconds, no matter what, for no obvious reason, e.g. even in the middle of playing wm-options.ulaw.
Here is a log of that:

  == Setting global variable 'SIPDOMAIN' to '192.168.2.246'
  == Using SIP RTP Audio TOS bits 184
  == Using SIP RTP Audio TOS bits 184 in TCLASS field.
  == Using SIP RTP Audio CoS mark 5
    -- Executing [*97@from-internal:1] Macro("PJSIP/808-0000005d", "user-callerid,") in new stack
    -- Executing [s@macro-user-callerid:1] Set("PJSIP/808-0000005d", "TOUCH_MONITOR=1605351429.126") in new stack
    -- Executing [s@macro-user-callerid:2] Set("PJSIP/808-0000005d", "AMPUSER=808") in new stack
    -- Executing [s@macro-user-callerid:3] Set("PJSIP/808-0000005d", "HOTDESCKCHAN=808-0000005d") in new stack
    -- Executing [s@macro-user-callerid:4] Set("PJSIP/808-0000005d", "HOTDESKEXTEN=808") in new stack
    -- Executing [s@macro-user-callerid:5] Set("PJSIP/808-0000005d", "HOTDESKCALL=0") in new stack
    -- Executing [s@macro-user-callerid:6] ExecIf("PJSIP/808-0000005d", "0?Set(HOTDESKCALL=1)") in new stack
    -- Executing [s@macro-user-callerid:7] ExecIf("PJSIP/808-0000005d", "0?Set(CALLERID(name)=)") in new stack
    -- Executing [s@macro-user-callerid:8] GotoIf("PJSIP/808-0000005d", "0?report") in new stack
    -- Executing [s@macro-user-callerid:9] ExecIf("PJSIP/808-0000005d", "1?Set(REALCALLERIDNUM=808)") in new stack
    -- Executing [s@macro-user-callerid:10] Set("PJSIP/808-0000005d", "AMPUSER=808") in new stack
    -- Executing [s@macro-user-callerid:11] GotoIf("PJSIP/808-0000005d", "0?limit") in new stack
    -- Executing [s@macro-user-callerid:12] Set("PJSIP/808-0000005d", "AMPUSERCIDNAME=Mirco Stange") in new stack
    -- Executing [s@macro-user-callerid:13] ExecIf("PJSIP/808-0000005d", "0?Set(__CIDMASQUERADING=TRUE)") in new stack
    -- Executing [s@macro-user-callerid:14] GotoIf("PJSIP/808-0000005d", "0?report") in new stack
    -- Executing [s@macro-user-callerid:15] Set("PJSIP/808-0000005d", "AMPUSERCID=808") in new stack
    -- Executing [s@macro-user-callerid:16] Set("PJSIP/808-0000005d", "__DIAL_OPTIONS=HhTtr") in new stack
    -- Executing [s@macro-user-callerid:17] Set("PJSIP/808-0000005d", "CALLERID(all)="Mirco Stange" <808>") in new stack
    -- Executing [s@macro-user-callerid:18] ExecIf("PJSIP/808-0000005d", "0?Set(CUSDIAL=)") in new stack
    -- Executing [s@macro-user-callerid:19] ExecIf("PJSIP/808-0000005d", "0?Set(CALLERID(all)="Mirco Stange" <808>)") in new stack
    -- Executing [s@macro-user-callerid:20] GotoIf("PJSIP/808-0000005d", "0?limit") in new stack
    -- Executing [s@macro-user-callerid:21] ExecIf("PJSIP/808-0000005d", "0?Set(GROUP(concurrency_limit)=808)") in new stack
    -- Executing [s@macro-user-callerid:22] ExecIf("PJSIP/808-0000005d", "0?Set(CHANNEL(language)=)") in new stack
    -- Executing [s@macro-user-callerid:23] NoOp("PJSIP/808-0000005d", "Macro Depth is 1") in new stack
    -- Executing [s@macro-user-callerid:24] GotoIf("PJSIP/808-0000005d", "1?report2:macroerror") in new stack
    -- Goto (macro-user-callerid,s,25)
    -- Executing [s@macro-user-callerid:25] GotoIf("PJSIP/808-0000005d", "0?continue") in new stack
    -- Executing [s@macro-user-callerid:26] ExecIf("PJSIP/808-0000005d", "1?Set(__CALLEE_ACCOUNCODE=)") in new stack
    -- Executing [s@macro-user-callerid:27] Set("PJSIP/808-0000005d", "__TTL=64") in new stack
    -- Executing [s@macro-user-callerid:28] GotoIf("PJSIP/808-0000005d", "1?continue") in new stack
    -- Goto (macro-user-callerid,s,44)
    -- Executing [s@macro-user-callerid:44] Set("PJSIP/808-0000005d", "CALLERID(number)=808") in new stack
    -- Executing [s@macro-user-callerid:45] Set("PJSIP/808-0000005d", "CALLERID(name)=Mirco Stange") in new stack
    -- Executing [s@macro-user-callerid:46] GotoIf("PJSIP/808-0000005d", "0?cnum") in new stack
    -- Executing [s@macro-user-callerid:47] Set("PJSIP/808-0000005d", "CDR(cnam)=Mirco Stange") in new stack
    -- Executing [s@macro-user-callerid:48] Set("PJSIP/808-0000005d", "CDR(cnum)=808") in new stack
    -- Executing [s@macro-user-callerid:49] Set("PJSIP/808-0000005d", "CHANNEL(language)=de") in new stack
    -- Executing [*97@from-internal:2] Set("PJSIP/808-0000005d", "CONNECTEDLINE(name-charset,i)=utf8") in new stack
    -- Executing [*97@from-internal:3] Set("PJSIP/808-0000005d", "CONNECTEDLINE(name,i)=Meine Voicemail") in new stack
    -- Executing [*97@from-internal:4] Set("PJSIP/808-0000005d", "CONNECTEDLINE(num,i)=808") in new stack
    -- Executing [*97@from-internal:5] Answer("PJSIP/808-0000005d", "") in new stack
       > 0x7fce5409bad0 -- Strict RTP learning after remote address set to: 192.168.2.170:5062
    -- Executing [*97@from-internal:6] Wait("PJSIP/808-0000005d", "1") in new stack
    -- Executing [*97@from-internal:7] Macro("PJSIP/808-0000005d", "get-vmcontext,808") in new stack
    -- Executing [s@macro-get-vmcontext:1] Set("PJSIP/808-0000005d", "VMCONTEXT=default") in new stack
    -- Executing [s@macro-get-vmcontext:2] GotoIf("PJSIP/808-0000005d", "0?200:300") in new stack
    -- Goto (macro-get-vmcontext,s,300)
    -- Executing [s@macro-get-vmcontext:300] NoOp("PJSIP/808-0000005d", "") in new stack
    -- Executing [*97@from-internal:8] Set("PJSIP/808-0000005d", "VMBOXEXISTSSTATUS=SUCCESS") in new stack
    -- Executing [*97@from-internal:9] GotoIf("PJSIP/808-0000005d", "1?mbexist") in new stack
    -- Goto (from-internal,*97,109)
    -- Executing [*97@from-internal:109] GotoIf("PJSIP/808-0000005d", "0?novmpw:vmpw") in new stack
    -- Goto (from-internal,*97,118)
    -- Executing [*97@from-internal:118] VoiceMailMain("PJSIP/808-0000005d", "808@default") in new stack
    -- <PJSIP/808-0000005d> Playing 'vm-password.ulaw' (language 'de')
       > 0x7fce5409bad0 -- Strict RTP switching to RTP target address 192.168.2.170:5062 as source
       > 0x7fce5409bad0 -- Strict RTP learning complete - Locking on source address 192.168.2.170:5062
[2020-11-14 11:57:16] DTMF[27118][C-0000004b]: channel.c:3987 __ast_read: DTMF begin '0' received on PJSIP/808-0000005d
[2020-11-14 11:57:16] DTMF[27118][C-0000004b]: channel.c:3991 __ast_read: DTMF begin ignored '0' on PJSIP/808-0000005d
[2020-11-14 11:57:16] DTMF[27118][C-0000004b]: channel.c:3873 __ast_read: DTMF end '0' received on PJSIP/808-0000005d, duration 80 ms
[2020-11-14 11:57:16] DTMF[27118][C-0000004b]: channel.c:3962 __ast_read: DTMF end passthrough '0' on PJSIP/808-0000005d
[2020-11-14 11:57:17] DTMF[27118][C-0000004b]: channel.c:3987 __ast_read: DTMF begin '0' received on PJSIP/808-0000005d
[2020-11-14 11:57:17] DTMF[27118][C-0000004b]: channel.c:3991 __ast_read: DTMF begin ignored '0' on PJSIP/808-0000005d
[2020-11-14 11:57:17] DTMF[27118][C-0000004b]: channel.c:3873 __ast_read: DTMF end '0' received on PJSIP/808-0000005d, duration 80 ms
[2020-11-14 11:57:17] DTMF[27118][C-0000004b]: channel.c:3962 __ast_read: DTMF end passthrough '0' on PJSIP/808-0000005d
[2020-11-14 11:57:18] DTMF[27118][C-0000004b]: channel.c:3987 __ast_read: DTMF begin '0' received on PJSIP/808-0000005d
[2020-11-14 11:57:18] DTMF[27118][C-0000004b]: channel.c:3991 __ast_read: DTMF begin ignored '0' on PJSIP/808-0000005d
[2020-11-14 11:57:18] DTMF[27118][C-0000004b]: channel.c:3873 __ast_read: DTMF end '0' received on PJSIP/808-0000005d, duration 80 ms
[2020-11-14 11:57:18] DTMF[27118][C-0000004b]: channel.c:3962 __ast_read: DTMF end passthrough '0' on PJSIP/808-0000005d
[2020-11-14 11:57:20] DTMF[27118][C-0000004b]: channel.c:3987 __ast_read: DTMF begin '0' received on PJSIP/808-0000005d
[2020-11-14 11:57:20] DTMF[27118][C-0000004b]: channel.c:3991 __ast_read: DTMF begin ignored '0' on PJSIP/808-0000005d
[2020-11-14 11:57:20] DTMF[27118][C-0000004b]: channel.c:3873 __ast_read: DTMF end '0' received on PJSIP/808-0000005d, duration 80 ms
[2020-11-14 11:57:20] DTMF[27118][C-0000004b]: channel.c:3962 __ast_read: DTMF end passthrough '0' on PJSIP/808-0000005d
    -- <PJSIP/808-0000005d> Playing 'vm-youhave.ulaw' (language 'de')
    -- <PJSIP/808-0000005d> Playing 'vm-no.ulaw' (language 'de')
    -- <PJSIP/808-0000005d> Playing 'vm-messages.ulaw' (language 'de')
    -- <PJSIP/808-0000005d> Playing 'vm-opts.ulaw' (language 'de')
    -- <PJSIP/808-0000005d> Playing 'vm-helpexit.ulaw' (language 'de')
[2020-11-14 11:57:38] DTMF[27118][C-0000004b]: channel.c:3987 __ast_read: DTMF begin '0' received on PJSIP/808-0000005d
[2020-11-14 11:57:38] DTMF[27118][C-0000004b]: channel.c:3991 __ast_read: DTMF begin ignored '0' on PJSIP/808-0000005d
[2020-11-14 11:57:38] DTMF[27118][C-0000004b]: channel.c:3873 __ast_read: DTMF end '0' received on PJSIP/808-0000005d, duration 80 ms
[2020-11-14 11:57:38] DTMF[27118][C-0000004b]: channel.c:3962 __ast_read: DTMF end passthrough '0' on PJSIP/808-0000005d
    -- <PJSIP/808-0000005d> Playing 'vm-options.ulaw' (language 'de')
  == Spawn extension (from-internal, *97, 118) exited non-zero on 'PJSIP/808-0000005d'
    -- Executing [h@from-internal:1] Macro("PJSIP/808-0000005d", "hangupcall") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("PJSIP/808-0000005d", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Executing [s@macro-hangupcall:3] ExecIf("PJSIP/808-0000005d", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s@macro-hangupcall:4] NoOp("PJSIP/808-0000005d", " montior file= ") in new stack
    -- Executing [s@macro-hangupcall:5] GotoIf("PJSIP/808-0000005d", "1?skipagi") in new stack
    -- Goto (macro-hangupcall,s,7)
    -- Executing [s@macro-hangupcall:7] Hangup("PJSIP/808-0000005d", "") in new stack
  == Spawn extension (macro-hangupcall, s, 7) exited non-zero on 'PJSIP/808-0000005d' in macro 'hangupcall'
  == Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/808-0000005d'

The extension is 808, mailbox pw is 0000. Note that the first 0 I hit for mailbox does not show up in the logs at all. Trying this a couple of times, I noticed that there is sometimes a delay between
<PJSIP/808-0000005d> Playing 'vm-password.ulaw' (language 'de')

and the following

> 0x7fce5409bad0 -- Strict RTP switching to RTP target address 192.168.2.170:5062 as source
> 0x7fce5409bad0 -- Strict RTP learning complete - Locking on source address 192.168.2.170:5062

Keys pressed in between are lost.

Calling the mailbox from the yealink phone does not seem to work at all. I do hear the voicemail prompt message, but any key I press does not show up at all. I am guessing that FreePBX does not “hear” anything from the phone. Here is a log (truncated top):

    Executing [*97@from-internal:5] Answer("PJSIP/883-00000061", "") in new stack
       > 0x7fce5409ab20 -- Strict RTP learning after remote address set to: 192.168.2.180:12342
    -- Executing [*97@from-internal:6] Wait("PJSIP/883-00000061", "1") in new stack
    -- Executing [*97@from-internal:7] Macro("PJSIP/883-00000061", "get-vmcontext,883") in new stack
    -- Executing [s@macro-get-vmcontext:1] Set("PJSIP/883-00000061", "VMCONTEXT=novm") in new stack
    -- Executing [s@macro-get-vmcontext:2] GotoIf("PJSIP/883-00000061", "0?200:300") in new stack
    -- Goto (macro-get-vmcontext,s,300)
    -- Executing [s@macro-get-vmcontext:300] NoOp("PJSIP/883-00000061", "") in new stack
    -- Executing [*97@from-internal:8] Set("PJSIP/883-00000061", "VMBOXEXISTSSTATUS=FAILED") in new stack
    -- Executing [*97@from-internal:9] GotoIf("PJSIP/883-00000061", "0?mbexist") in new stack
    -- Executing [*97@from-internal:10] VoiceMailMain("PJSIP/883-00000061", "") in new stack
    -- <PJSIP/883-00000061> Playing 'vm-login.ulaw' (language 'de')
    -- <PJSIP/883-00000061> Playing 'vm-password.ulaw' (language 'de')
    -- Incorrect password '' for user '883' (context = default)
    -- <PJSIP/883-00000061> Playing 'vm-incorrect-mailbox.ulaw' (language 'de')
[2020-11-14 12:06:42] NOTICE[2819]: res_pjsip_sdp_rtp.c:148 rtp_check_timeout: Disconnecting channel 'PJSIP/883-00000061' for lack of audio RTP activity in 30 seconds
[2020-11-14 12:06:42] WARNING[31510][C-0000004f]: app_voicemail.c:11334 vm_authenticate: Couldn't read username
    -- Executing [h@from-internal:1] Macro("PJSIP/883-00000061", "hangupcall") in new stack
    -- Executing [s@macro-hangupcall:1] GotoIf("PJSIP/883-00000061", "1?theend") in new stack
    -- Goto (macro-hangupcall,s,3)
    -- Executing [s@macro-hangupcall:3] ExecIf("PJSIP/883-00000061", "0?Set(CDR(recordingfile)=)") in new stack
    -- Executing [s@macro-hangupcall:4] NoOp("PJSIP/883-00000061", " montior file= ") in new stack
    -- Executing [s@macro-hangupcall:5] GotoIf("PJSIP/883-00000061", "1?skipagi") in new stack
    -- Goto (macro-hangupcall,s,7)
    -- Executing [s@macro-hangupcall:7] Hangup("PJSIP/883-00000061", "") in new stack
  == Spawn extension (macro-hangupcall, s, 7) exited non-zero on 'PJSIP/883-00000061' in macro 'hangupcall'
  == Spawn extension (from-internal, h, 1) exited non-zero on 'PJSIP/883-00000061'

Furthermore, I can make a call from yealink to phonerLite, phonerLite rings, I can pick up the call. However, no sound seems to travel from yealink to phonerLite.
When I hangup the call on yealink, FreePBX does not even seem to notice. PhonerLite shows the call as connected. After a some seconds, FreePBX terminates the call due to inactivity
[2020-11-14 12:12:53] NOTICE[2819]: res_pjsip_sdp_rtp.c:148 rtp_check_timeout: Disconnecting channel 'PJSIP/883-00000062' for lack of audio RTP activity in 33 seconds.

When making a call from Yealink to PhonerLite and not picking up, I get the voicemail prompt. However, anything I record on the vm is apparently lost.

When making a call from PhonerLite to yealink, the phone rings and I can pickup the call. I am not sure about sound - unable to test atm - but when I hangup the call on phonerLite or on yealink, the call stays open until ~30 secs until it gets disconnected.
When I press the hold key on PhonerLite, nothing appears to happen at all.

None of this appears to make any sense to me. I am just getting started with the system and so I have no idea where to look or what I could have possibly made wrong.

Stewart1 · November 14, 2020, 2:23pm

In Asterisk SIP Settings, confirm that External Address and Local Networks are correctly set. If you change these, restart Asterisk.

Confirm that the virtual machine is using bridged networking with no firewall between it and the LAN.

Confirm that anything related to NAT or STUN at the device is turned off. On Yealink, NAT should be Disabled and STUN Server blank.

If you still have trouble, at the Asterisk command prompt type
pjsip set logger on
make a failing test call, paste the complete Asterisk log for the call (which will now include a SIP trace) at pastebin.freepbx.org and post the link here.

system · June 3, 2021, 10:58pm

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