*50* always going to comedian mail

[compsos]

Hi S
Got a system that will not directly go to the inbox from the phones. (ie) dialing *50* or *97 gives the result of *51*. The dialplan shows both being passed to sarkhpe.
The only things I find unusual in the agi debug is the "vm_authenticate: Couldn't read username" and {cid} is shown as our trunks number. This issue did arise in version 4 and has followed through to v5. Is it something wrong in the DB?

-- Executing [*50*@internal:1] AGI("SIP/501-00000000", "sarkhpe,OutCos,*50*,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe
<SIP/501-00000000>AGI Tx >> agi_request: sarkhpe
<SIP/501-00000000>AGI Tx >> agi_channel: SIP/501-00000000
<SIP/501-00000000>AGI Tx >> agi_language: en_AU
<SIP/501-00000000>AGI Tx >> agi_type: SIP
<SIP/501-00000000>AGI Tx >> agi_uniqueid: 1493087413.0
<SIP/501-00000000>AGI Tx >> agi_version: 11.13.1~dfsg-2+deb8u2
<SIP/501-00000000>AGI Tx >> agi_callerid: {cid}
<SIP/501-00000000>AGI Tx >> agi_calleridname: Gordon
<SIP/501-00000000>AGI Tx >> agi_callingpres: 0
<SIP/501-00000000>AGI Tx >> agi_callingani2: 0
<SIP/501-00000000>AGI Tx >> agi_callington: 0
<SIP/501-00000000>AGI Tx >> agi_callingtns: 0
<SIP/501-00000000>AGI Tx >> agi_dnid: *50*
<SIP/501-00000000>AGI Tx >> agi_rdnis: unknown
<SIP/501-00000000>AGI Tx >> agi_context: internal
<SIP/501-00000000>AGI Tx >> agi_extension: *50*
<SIP/501-00000000>AGI Tx >> agi_priority: 1
<SIP/501-00000000>AGI Tx >> agi_enhanced: 0.0
<SIP/501-00000000>AGI Tx >> agi_accountcode:
<SIP/501-00000000>AGI Tx >> agi_threadid: 139736514815744
<SIP/501-00000000>AGI Tx >> agi_arg_1: OutCos
<SIP/501-00000000>AGI Tx >> agi_arg_2: *50*
<SIP/501-00000000>AGI Tx >> agi_arg_3:
<SIP/501-00000000>AGI Tx >> agi_arg_4:
<SIP/501-00000000>AGI Tx >>
<SIP/501-00000000>AGI Rx << GET VARIABLE DEBUG
<SIP/501-00000000>AGI Tx >> 200 result=0
<SIP/501-00000000>AGI Rx << GET VARIABLE EXTLEN
<SIP/501-00000000>AGI Tx >> 200 result=1 (3)
<SIP/501-00000000>AGI Rx << GET VARIABLE ASTDLIM
<SIP/501-00000000>AGI Tx >> 200 result=1 (,)
<SIP/501-00000000>AGI Rx << GET VARIABLE ABSTIMEOUT
<SIP/501-00000000>AGI Tx >> 200 result=1 (14400)
<SIP/501-00000000>AGI Rx << DATABASE GET "STAT" "OCSTAT"
<SIP/501-00000000>AGI Tx >> 200 result=0
<SIP/501-00000000>AGI Rx << SET PRIORITY 1
<SIP/501-00000000>AGI Tx >> 200 result=0
<SIP/501-00000000>AGI Rx << SET EXTENSION *50*
<SIP/501-00000000>AGI Tx >> 200 result=0
<SIP/501-00000000>AGI Rx << SET CONTEXT qrxvtmny
<SIP/501-00000000>AGI Tx >> 200 result=0
    -- <SIP/501-00000000>AGI Script sarkhpe completed, returning 0
    -- Executing [*50*@qrxvtmny:1] AGI("SIP/501-00000000", "sarkhpe,*50*,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe
<SIP/501-00000000>AGI Tx >> agi_request: sarkhpe
<SIP/501-00000000>AGI Tx >> agi_channel: SIP/501-00000000
<SIP/501-00000000>AGI Tx >> agi_language: en_AU
<SIP/501-00000000>AGI Tx >> agi_type: SIP
<SIP/501-00000000>AGI Tx >> agi_uniqueid: 1493087413.0
<SIP/501-00000000>AGI Tx >> agi_version: 11.13.1~dfsg-2+deb8u2
<SIP/501-00000000>AGI Tx >> agi_callerid: {cid}
<SIP/501-00000000>AGI Tx >> agi_calleridname: Gordon
<SIP/501-00000000>AGI Tx >> agi_callingpres: 0
<SIP/501-00000000>AGI Tx >> agi_callingani2: 0
<SIP/501-00000000>AGI Tx >> agi_callington: 0
<SIP/501-00000000>AGI Tx >> agi_callingtns: 0
<SIP/501-00000000>AGI Tx >> agi_dnid: *50*
<SIP/501-00000000>AGI Tx >> agi_rdnis: unknown
<SIP/501-00000000>AGI Tx >> agi_context: qrxvtmny
<SIP/501-00000000>AGI Tx >> agi_extension: *50*
<SIP/501-00000000>AGI Tx >> agi_priority: 1
<SIP/501-00000000>AGI Tx >> agi_enhanced: 0.0
<SIP/501-00000000>AGI Tx >> agi_accountcode:
<SIP/501-00000000>AGI Tx >> agi_threadid: 139736514815744
<SIP/501-00000000>AGI Tx >> agi_arg_1: *50*
<SIP/501-00000000>AGI Tx >> agi_arg_2:
<SIP/501-00000000>AGI Tx >> agi_arg_3:
<SIP/501-00000000>AGI Tx >>
<SIP/501-00000000>AGI Rx << GET VARIABLE DEBUG
<SIP/501-00000000>AGI Tx >> 200 result=0
<SIP/501-00000000>AGI Rx << GET VARIABLE EXTLEN
<SIP/501-00000000>AGI Tx >> 200 result=1 (3)
<SIP/501-00000000>AGI Rx << GET VARIABLE ASTDLIM
<SIP/501-00000000>AGI Tx >> 200 result=1 (,)
<SIP/501-00000000>AGI Rx << GET VARIABLE ABSTIMEOUT
<SIP/501-00000000>AGI Tx >> 200 result=1 (14400)
<SIP/501-00000000>AGI Rx << ANSWER
       > 0x7f16cc06d0e0 -- Probation passed - setting RTP source address to xxx.xxx.xxx.xxx:11798
<SIP/501-00000000>AGI Tx >> 200 result=0
<SIP/501-00000000>AGI Rx << EXEC Wait 0.5
    -- AGI Script Executing Application: (Wait) Options: (0.5)
<SIP/501-00000000>AGI Tx >> 200 result=0
<SIP/501-00000000>AGI Rx << EXEC VoiceMailMain {cid}
    -- AGI Script Executing Application: (VoiceMailMain) Options: ({cid})
    -- <SIP/501-00000000> Playing 'vm-login.g722' (language 'en_AU')
[2017-04-25 12:30:17] WARNING[15176][C-00000000]: app_voicemail.c:10545 vm_authenticate: Couldn't read username
<SIP/501-00000000>AGI Tx >> 200 result=0
    -- <SIP/501-00000000>AGI Script sarkhpe completed, returning 4
  == Spawn extension (qrxvtmny, *50*, 1) exited non-zero on 'SIP/501-00000000'

[sysadmin]

It looks like you aren't sending a CLI.   If you look at the line

Code Select Expand

<SIP/501-00000000>AGI Tx >> agi_callerid: {cid}

Here is an example from a test system here, you'll see the CLI is present.   The AGI passes the CLI to VoiceMailMain.  If the CLI is empty then VoceMailMain will request it (effectively *51*).

Code Select Expand

AGI Debugging Enabled
  == Using SIP RTP CoS mark 5
    -- Executing [*50*@internal:1] AGI("SIP/401-0000001e", "sarkhpe,OutCos,*50*,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe
<SIP/401-0000001e>AGI Tx >> agi_request: sarkhpe
<SIP/401-0000001e>AGI Tx >> agi_channel: SIP/401-0000001e
<SIP/401-0000001e>AGI Tx >> agi_language: en-gb
<SIP/401-0000001e>AGI Tx >> agi_type: SIP
<SIP/401-0000001e>AGI Tx >> agi_uniqueid: 1494073903.56
<SIP/401-0000001e>AGI Tx >> agi_version: 11.13.1~dfsg-2+b1
<SIP/401-0000001e>AGI Tx >> agi_callerid: 401
<SIP/401-0000001e>AGI Tx >> agi_calleridname: Ext401
<SIP/401-0000001e>AGI Tx >> agi_callingpres: 0
<SIP/401-0000001e>AGI Tx >> agi_callingani2: 0
<SIP/401-0000001e>AGI Tx >> agi_callington: 0
<SIP/401-0000001e>AGI Tx >> agi_callingtns: 0
<SIP/401-0000001e>AGI Tx >> agi_dnid: *50*
<SIP/401-0000001e>AGI Tx >> agi_rdnis: unknown
<SIP/401-0000001e>AGI Tx >> agi_context: internal
<SIP/401-0000001e>AGI Tx >> agi_extension: *50*
<SIP/401-0000001e>AGI Tx >> agi_priority: 1
<SIP/401-0000001e>AGI Tx >> agi_enhanced: 0.0
<SIP/401-0000001e>AGI Tx >> agi_accountcode:
<SIP/401-0000001e>AGI Tx >> agi_threadid: 139816084096768
<SIP/401-0000001e>AGI Tx >> agi_arg_1: OutCos
<SIP/401-0000001e>AGI Tx >> agi_arg_2: *50*
<SIP/401-0000001e>AGI Tx >> agi_arg_3:
<SIP/401-0000001e>AGI Tx >> agi_arg_4:
<SIP/401-0000001e>AGI Tx >>
<SIP/401-0000001e>AGI Rx << GET VARIABLE DEBUG
<SIP/401-0000001e>AGI Tx >> 200 result=0
<SIP/401-0000001e>AGI Rx << GET VARIABLE EXTLEN
<SIP/401-0000001e>AGI Tx >> 200 result=1 (3)
<SIP/401-0000001e>AGI Rx << GET VARIABLE ASTDLIM
<SIP/401-0000001e>AGI Tx >> 200 result=1 (,)
<SIP/401-0000001e>AGI Rx << GET VARIABLE ABSTIMEOUT
<SIP/401-0000001e>AGI Tx >> 200 result=1 (14400)
<SIP/401-0000001e>AGI Rx << DATABASE GET "STAT" "OCSTAT"
<SIP/401-0000001e>AGI Tx >> 200 result=0
<SIP/401-0000001e>AGI Rx << SET PRIORITY 1
<SIP/401-0000001e>AGI Tx >> 200 result=0
<SIP/401-0000001e>AGI Rx << SET EXTENSION *50*
<SIP/401-0000001e>AGI Tx >> 200 result=0
<SIP/401-0000001e>AGI Rx << SET CONTEXT 401opencos
<SIP/401-0000001e>AGI Tx >> 200 result=0
    -- <SIP/401-0000001e>AGI Script sarkhpe completed, returning 0
    -- Executing [*50*@401opencos:1] AGI("SIP/401-0000001e", "sarkhpe,OutCluster,*50*,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe
<SIP/401-0000001e>AGI Tx >> agi_request: sarkhpe
<SIP/401-0000001e>AGI Tx >> agi_channel: SIP/401-0000001e
<SIP/401-0000001e>AGI Tx >> agi_language: en-gb
<SIP/401-0000001e>AGI Tx >> agi_type: SIP
<SIP/401-0000001e>AGI Tx >> agi_uniqueid: 1494073903.56
<SIP/401-0000001e>AGI Tx >> agi_version: 11.13.1~dfsg-2+b1
<SIP/401-0000001e>AGI Tx >> agi_callerid: 401
<SIP/401-0000001e>AGI Tx >> agi_calleridname: Ext401
<SIP/401-0000001e>AGI Tx >> agi_callingpres: 0
<SIP/401-0000001e>AGI Tx >> agi_callingani2: 0
<SIP/401-0000001e>AGI Tx >> agi_callington: 0
<SIP/401-0000001e>AGI Tx >> agi_callingtns: 0
<SIP/401-0000001e>AGI Tx >> agi_dnid: *50*
<SIP/401-0000001e>AGI Tx >> agi_rdnis: unknown
<SIP/401-0000001e>AGI Tx >> agi_context: 401opencos
<SIP/401-0000001e>AGI Tx >> agi_extension: *50*
<SIP/401-0000001e>AGI Tx >> agi_priority: 1
<SIP/401-0000001e>AGI Tx >> agi_enhanced: 0.0
<SIP/401-0000001e>AGI Tx >> agi_accountcode:
<SIP/401-0000001e>AGI Tx >> agi_threadid: 139816084096768
<SIP/401-0000001e>AGI Tx >> agi_arg_1: OutCluster
<SIP/401-0000001e>AGI Tx >> agi_arg_2: *50*
<SIP/401-0000001e>AGI Tx >> agi_arg_3:
<SIP/401-0000001e>AGI Tx >> agi_arg_4:
<SIP/401-0000001e>AGI Tx >>
<SIP/401-0000001e>AGI Rx << GET VARIABLE DEBUG
<SIP/401-0000001e>AGI Tx >> 200 result=0
<SIP/401-0000001e>AGI Rx << GET VARIABLE EXTLEN
<SIP/401-0000001e>AGI Tx >> 200 result=1 (3)
<SIP/401-0000001e>AGI Rx << GET VARIABLE ASTDLIM
<SIP/401-0000001e>AGI Tx >> 200 result=1 (,)
<SIP/401-0000001e>AGI Rx << GET VARIABLE ABSTIMEOUT
<SIP/401-0000001e>AGI Tx >> 200 result=1 (14400)
<SIP/401-0000001e>AGI Rx << SET PRIORITY 1
<SIP/401-0000001e>AGI Tx >> 200 result=0
<SIP/401-0000001e>AGI Rx << SET EXTENSION *50*
<SIP/401-0000001e>AGI Tx >> 200 result=0
<SIP/401-0000001e>AGI Rx << SET CONTEXT qrxvtmny
<SIP/401-0000001e>AGI Tx >> 200 result=0
    -- <SIP/401-0000001e>AGI Script sarkhpe completed, returning 0
    -- Executing [*50*@qrxvtmny:1] AGI("SIP/401-0000001e", "sarkhpe,*50*,,") in new stack
    -- Launched AGI Script /usr/share/asterisk/agi-bin/sarkhpe
<SIP/401-0000001e>AGI Tx >> agi_request: sarkhpe
<SIP/401-0000001e>AGI Tx >> agi_channel: SIP/401-0000001e
<SIP/401-0000001e>AGI Tx >> agi_language: en-gb
<SIP/401-0000001e>AGI Tx >> agi_type: SIP
<SIP/401-0000001e>AGI Tx >> agi_uniqueid: 1494073903.56
<SIP/401-0000001e>AGI Tx >> agi_version: 11.13.1~dfsg-2+b1
<SIP/401-0000001e>AGI Tx >> agi_callerid: 401
<SIP/401-0000001e>AGI Tx >> agi_calleridname: Ext401
<SIP/401-0000001e>AGI Tx >> agi_callingpres: 0
<SIP/401-0000001e>AGI Tx >> agi_callingani2: 0
<SIP/401-0000001e>AGI Tx >> agi_callington: 0
<SIP/401-0000001e>AGI Tx >> agi_callingtns: 0
<SIP/401-0000001e>AGI Tx >> agi_dnid: *50*
<SIP/401-0000001e>AGI Tx >> agi_rdnis: unknown
<SIP/401-0000001e>AGI Tx >> agi_context: qrxvtmny
<SIP/401-0000001e>AGI Tx >> agi_extension: *50*
<SIP/401-0000001e>AGI Tx >> agi_priority: 1
<SIP/401-0000001e>AGI Tx >> agi_enhanced: 0.0
<SIP/401-0000001e>AGI Tx >> agi_accountcode:
<SIP/401-0000001e>AGI Tx >> agi_threadid: 139816084096768
<SIP/401-0000001e>AGI Tx >> agi_arg_1: *50*
<SIP/401-0000001e>AGI Tx >> agi_arg_2:
<SIP/401-0000001e>AGI Tx >> agi_arg_3:
<SIP/401-0000001e>AGI Tx >>
<SIP/401-0000001e>AGI Rx << GET VARIABLE DEBUG
<SIP/401-0000001e>AGI Tx >> 200 result=0
<SIP/401-0000001e>AGI Rx << GET VARIABLE EXTLEN
<SIP/401-0000001e>AGI Tx >> 200 result=1 (3)
<SIP/401-0000001e>AGI Rx << GET VARIABLE ASTDLIM
<SIP/401-0000001e>AGI Tx >> 200 result=1 (,)
<SIP/401-0000001e>AGI Rx << GET VARIABLE ABSTIMEOUT
<SIP/401-0000001e>AGI Tx >> 200 result=1 (14400)
<SIP/401-0000001e>AGI Rx << ANSWER
       > 0x7f29c0017630 -- Probation passed - setting RTP source address to 172.16.0.74:55076
<SIP/401-0000001e>AGI Tx >> 200 result=0
<SIP/401-0000001e>AGI Rx << EXEC Wait 0.5
    -- AGI Script Executing Application: (Wait) Options: (0.5)
<SIP/401-0000001e>AGI Tx >> 200 result=0
<SIP/401-0000001e>AGI Rx << EXEC VoiceMailMain 401
    -- AGI Script Executing Application: (VoiceMailMain) Options: (401)
    -- <SIP/401-0000001e> Playing 'vm-password.gsm' (language 'en-gb')
[2017-05-06 13:31:45] WARNING[5289][C-00000021]: app_voicemail.c:10587 vm_authenticate: Unable to read password
<SIP/401-0000001e>AGI Tx >> 200 result=0
    -- <SIP/401-0000001e>AGI Script sarkhpe completed, returning 4
  == Spawn extension (qrxvtmny, *50*, 1) exited non-zero on 'SIP/401-0000001e'

[compsos]

Finally tracked it down
In the Stanza "Asterisk" tab we had the callerid="$desc" <Ext Number>. It seems the system must have considered this too long and just did not pass it through. So in the logs it was blank.