Caller ID not coming through from IAX incoming call [SOLVED]

Asterisk Asterisk Support
1

I’m using V11.7, with SIP clients and an IAX2 trunk to the VoIP provider.
CallerID is fine between extensions (SIP clients), and also on outgoing calls (i.e. the callee sees the company phone number). However on an incoming call it doesn’t seem to be reaching the dial plan. I can see the callers number in the IAX2 debug output.
I’ve added some debug steps to the IAX’s Context in extensions.conf -
exten = s,1,Noop(Callerid is ${CALLERID()})
exten = s,n,Noop(Callerid num is ${CALLERID(num)})
exten = s,n,Noop(Callerid num-pres is ${CALLERID(num-pres)})
exten = s,n,Noop(Callerid name is ${CALLERID(name)})
exten = s,n,Noop(Callerid all is ${CALLERID(all)})
exten = s,n,Goto(voicemenu-custom-1,s,1)
which just produces:
– Executing [s@DID_lns:1] NoOp(“IAX2/lns-4311”, "Callerid is ") in new stack
– Executing [s@DID_lns:2] NoOp(“IAX2/lns-4311”, "Callerid num is ") in new stack
– Executing [s@DID_lns:3] NoOp(“IAX2/lns-4311”, “Callerid num-pres is allowed_passed_screen”) in new stack
– Executing [s@DID_lns:4] NoOp(“IAX2/lns-4311”, “Callerid name is New User”) in new stack
– Executing [s@DID_lns:5] NoOp(“IAX2/lns-4311”, “Callerid all is “New User” <>”) in new stack
– Executing [s@DID_lns:6] Goto(“IAX2/lns-4311”, “voicemenu-custom-1,s,1”) in new stack

Anyone have any ideas as to why the CallerID isn’t getting through (or is being lost)?

2

What is the IAX2 configuration and the iax2 debug?

3

iax.conf (commented stuff removed) is

[general]
bindaddr=192.168.100.15:4569
bandwidth=high
disallow=lpc10
jitterbuffer=no
forcejitterbuffer=no
autokill=yes

The IAX2 is set up (rightly or wrongly…) in users.conf:

[lns]
host = iax-out.provider.net
username = ouruser
secret = ourSECRET
trunkname = OurProvider
context = DID_lns
hasexten = no
hasiax = yes
hassip = no
registeriax = no
registersip = no
trunk = no
fromuser =
authuser =
insecure = no
disallow = all
allow = ulaw,alaw,gsm,g726
type = peer

With ‘iax2 set debug on’ and core verbose & debug set to 9, the iax2 debug is

Rx-Frame Retry[ No] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ
Timestamp: 00002ms SCall: 04200 DCall: 00000 [88.111.69.97:37028]
USERNAME : 302
REFRESH : 60
CALLTOKEN : Present
FW BLOCK DATA : 15 bytes

Tx-Frame Retry[ No] – OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN
Timestamp: 00002ms SCall: 00001 DCall: 04200 [88.111.69.97:37028]
CALLTOKEN : 51 bytes

Rx-Frame Retry[Yes] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ
Timestamp: 00002ms SCall: 04200 DCall: 00000 [88.111.69.97:37028]
USERNAME : 302
REFRESH : 60
CALLTOKEN : Present
FW BLOCK DATA : 15 bytes

Tx-Frame Retry[ No] – OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN
Timestamp: 00002ms SCall: 00001 DCall: 04200 [88.111.69.97:37028]
CALLTOKEN : 51 bytes

Rx-Frame Retry[Yes] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ
Timestamp: 00002ms SCall: 04200 DCall: 00000 [88.111.69.97:37028]
USERNAME : 302
REFRESH : 60
CALLTOKEN : Present
FW BLOCK DATA : 15 bytes

Tx-Frame Retry[ No] – OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN
Timestamp: 00002ms SCall: 00001 DCall: 04200 [88.111.69.97:37028]
CALLTOKEN : 51 bytes

Rx-Frame Retry[Yes] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ
Timestamp: 00002ms SCall: 04200 DCall: 00000 [88.111.69.97:37028]
USERNAME : 302
REFRESH : 60
CALLTOKEN : Present
FW BLOCK DATA : 15 bytes

Tx-Frame Retry[ No] – OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN
Timestamp: 00002ms SCall: 00001 DCall: 04200 [88.111.69.97:37028]
CALLTOKEN : 51 bytes

Rx-Frame Retry[ No] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW
Timestamp: 00019ms SCall: 07196 DCall: 00000 [109.224.241.74:4569]
VERSION : 2
CALLED NUMBER : s
CODEC_PREFS : ()
CALLING NUMBER : 07767333777
CALLING PRESNTN : 0
CALLING TYPEOFN : 0
CALLING TRANSIT : 0
CALLING NAME :
LANGUAGE : en
USERNAME : lns
FORMAT : 8
FORMAT2 : alaw
CAPABILITY : 65407
CAPABILITY2 : Unknown
ADSICPE : 2
DATE TIME : 2016-06-28 14:12:26

Tx-Frame Retry[ No] – OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN
Timestamp: 00019ms SCall: 00001 DCall: 07196 [109.224.241.74:4569]
CALLTOKEN : 51 bytes

Rx-Frame Retry[ No] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW
Timestamp: 00030ms SCall: 07196 DCall: 00000 [109.224.241.74:4569]
VERSION : 2
CALLED NUMBER : s
CODEC_PREFS : ()
CALLING NUMBER : 07767333777
CALLING PRESNTN : 0
CALLING TYPEOFN : 0
CALLING TRANSIT : 0
CALLING NAME :
LANGUAGE : en
USERNAME : lns
FORMAT : 8
FORMAT2 : alaw
CAPABILITY : 65407
CAPABILITY2 : Unknown
ADSICPE : 2
DATE TIME : 2016-06-28 14:12:26
CALLTOKEN : 51 bytes

Tx-Frame Retry[000] – OSeqno: 000 ISeqno: 001 Type: IAX Subclass: AUTHREQ
Timestamp: 00015ms SCall: 06227 DCall: 07196 [109.224.241.74:4569]
AUTHMETHODS : 3
CHALLENGE : \x31\x31\x31\x32\x38\x39\x36\x38\x33
USERNAME : lns

Rx-Frame Retry[ No] – OSeqno: 001 ISeqno: 001 Type: IAX Subclass: AUTHREP
Timestamp: 00040ms SCall: 07196 DCall: 06227 [109.224.241.74:4569]
MD5 RESULT : f4c6b11aa5f8a0fc0b73df611e5fe5a3

-- Accepting AUTHENTICATED call from 109.224.241.74:
--        > requested format = alaw,
--        > requested prefs = (),
--        > actual format = ulaw,
--        > host prefs = (ulaw|alaw|gsm|g726),
--        > priority = mine

Tx-Frame Retry[000] – OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACCEPT
Timestamp: 00025ms SCall: 06227 DCall: 07196 [109.224.241.74:4569]
FORMAT : 4
FORMAT2 : ulaw

-- Executing [s@DID_lns:1] NoOp("IAX2/lns-6227", "Callerid is ") in new stack
-- Executing [s@DID_lns:2] NoOp("IAX2/lns-6227", "Callerid num is ") in new stack
-- Executing [s@DID_lns:3] NoOp("IAX2/lns-6227", "Callerid num-pres is allowed_passed_screen") in new stack
-- Executing [s@DID_lns:4] NoOp("IAX2/lns-6227", "Callerid name is New User") in new stack
-- Executing [s@DID_lns:5] NoOp("IAX2/lns-6227", "Callerid all is "New User" <>") in new stack
-- Executing [s@DID_lns:6] Goto("IAX2/lns-6227", "voicemenu-custom-1,s,1") in new stack
-- Goto (voicemenu-custom-1,s,1)
-- Executing [s@voicemenu-custom-1:1] NoOp("IAX2/lns-6227", "Incoming") in new stack
-- Executing [s@voicemenu-custom-1:2] Wait("IAX2/lns-6227", "1") in new stack

Rx-Frame Retry[ No] – OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK
Timestamp: 00025ms SCall: 07196 DCall: 06227 [109.224.241.74:4569]
– Executing [s@voicemenu-custom-1:3] Answer(“IAX2/lns-6227”, “”) in new stack
Tx-Frame Retry[000] – OSeqno: 002 ISeqno: 002 Type: CONTROL Subclass: ANSWER
Timestamp: 01026ms SCall: 06227 DCall: 07196 [109.224.241.74:4569]
Tx-Frame Retry[000] – OSeqno: 003 ISeqno: 002 Type: CONTROL Subclass: (255?)
Timestamp: 01029ms SCall: 06227 DCall: 07196 [109.224.241.74:4569]
Rx-Frame Retry[ No] – OSeqno: 002 ISeqno: 003 Type: IAX Subclass: ACK
Timestamp: 01026ms SCall: 07196 DCall: 06227 [109.224.241.74:4569]
Rx-Frame Retry[ No] – OSeqno: 002 ISeqno: 004 Type: IAX Subclass: ACK
Timestamp: 01029ms SCall: 07196 DCall: 06227 [109.224.241.74:4569]
Rx-Frame Retry[ No] – OSeqno: 002 ISeqno: 004 Type: VOICE Subclass: 4
Timestamp: 01108ms SCall: 07196 DCall: 06227 [109.224.241.74:4569]
Tx-Frame Retry[-01] – OSeqno: 004 ISeqno: 003 Type: IAX Subclass: ACK
Timestamp: 01108ms SCall: 06227 DCall: 07196 [109.224.241.74:4569]
– Executing [s@voicemenu-custom-1:4] Wait(“IAX2/lns-6227”, “1”) in new stack
– Executing [s@voicemenu-custom-1:5] Set(“IAX2/lns-6227”, “TIMEOUT(digit)=3”) in new stack
– Digit timeout set to 3.000
– Executing [s@voicemenu-custom-1:6] Set(“IAX2/lns-6227”, “TIMEOUT(response)=7”) in new stack
– Response timeout set to 7.000
– Executing [s@voicemenu-custom-1:7] BackGround(“IAX2/lns-6227”, “custom/ln_greeting”) in new stack
– <IAX2/lns-6227> Playing ‘custom/ln_greeting.slin’ (language ‘en’)
Tx-Frame Retry[000] – OSeqno: 004 ISeqno: 003 Type: VOICE Subclass: 4
Timestamp: 02100ms SCall: 06227 DCall: 07196 [109.224.241.74:4569]
Rx-Frame Retry[ No] – OSeqno: 003 ISeqno: 005 Type: IAX Subclass: ACK
Timestamp: 02100ms SCall: 07196 DCall: 06227 [109.224.241.74:4569]
Rx-Frame Retry[ No] – OSeqno: 003 ISeqno: 005 Type: IAX Subclass: HANGUP
Timestamp: 05106ms SCall: 07196 DCall: 06227 [109.224.241.74:4569]
CAUSE CODE : 16

Tx-Frame Retry[-01] – OSeqno: 005 ISeqno: 004 Type: IAX Subclass: ACK
Timestamp: 05106ms SCall: 06227 DCall: 07196 [109.224.241.74:4569]
== Spawn extension (voicemenu-custom-1, s, 7) exited non-zero on ‘IAX2/lns-6227’
– Hungup ‘IAX2/lns-6227’

4

Finally found the answer: the IAX setup in users.conf needed
callerid = asreceived