Project

General

Profile

Bug #7252

Reverse lookup ne fonctionne pas

Added by Nico JB 3 months ago. Updated about 1 month ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
Directory
Target version:
-
Security issue:
No
In versions:
18.03
Read documentation?:
Yes

Description

Bonjour,

Depuis la mise à jour de mon Wazo en 18.03 le reverse lookup sur mon téléphone ne fonctionne plus... par contre, avec l'api cela fonctionne :
https://srv-xivo2:9489/0.1/directories/reverse/default/879f753c-9e06-4fae-b55c-ed17fad64074?exten=060xxxxxx

Je pense que c'est parce que sur mon téléphone (Snom 821), le numéro appelant s'affiche en 336xxxxxxxx

Mais le fichier /etc/xivo/asterisk/xivo_in_callerid.conf est bien paramétré, :


[national2]
comment = modification à effectuer pour Keyyo et IPPI
callerid = ^33\d{9}$
strip = 2
add = 0

[national3]
comment = modification à effectuer pour Keyyo et IPPI
callerid = ^\+33\d{9}$
strip = 3
add = 0

Une idée ?

always-reverse-lookup.patch View (639 Bytes) Sébastien Duthil, 2018-11-07 13:10

History

#1 Updated by Nico JB 3 months ago

Bonjour,

Auriez-vous une réponse à m'apporter ?
Le problème touche tout les wazo depuis la 17.17.

Cordialement,

#2 Updated by Pascal Cadotte-Michaud 2 months ago

Bonjour,

lors d'un appel entrant qu'y a-t-il dans le log Asterisk, dans xivo-dird-phoned.log et wazo-dird.log?

Est-ce qu'une requête est fait sur wazo-dird?
Si oui est-ce que le numéro dans la requête est 336... ou 06...?

#3 Updated by Nico JB 2 months ago

Bonjour,

Il n'y a rien dans xivo-dird-phoned.log, ni xivo-dird.log. Le fichie wazo-dird.log n'existe pas.

Voici une trace sip :

[Oct  3 16:04:23]   == Using SIP RTP CoS mark 5
[Oct  3 16:04:23]        > 0x7f60743e0b00 -- Strict RTP learning after remote address set to: 83.136.163.36:54160
[Oct  3 16:04:23]     -- Executing [334xxxxxxxx@from-extern:1] Set("SIP/keyyo.net-00005a22", "XIVO_BASE_CONTEXT=from-extern") in new stack
[Oct  3 16:04:23]     -- Executing [334xxxxxxxx@from-extern:2] Set("SIP/keyyo.net-00005a22", "XIVO_BASE_EXTEN=334xxxxxxxx") in new stack
[Oct  3 16:04:23]     -- Executing [334xxxxxxxx@from-extern:3] GotoIf("SIP/keyyo.net-00005a22", "?:action") in new stack
[Oct  3 16:04:23]     -- Goto (from-extern,334xxxxxxxx,5)
[Oct  3 16:04:23]     -- Executing [334xxxxxxxx@from-extern:5] Gosub("SIP/keyyo.net-00005a22", "did,s,1(370,)") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:1] Set("SIP/keyyo.net-00005a22", "XIVO_DSTNUM=334xxxxxxxx") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:2] Set("SIP/keyyo.net-00005a22", "XIVO_CONTEXT=from-extern") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:3] Set("SIP/keyyo.net-00005a22", "XIVO_PRESUBR_GLOBAL_NAME=DID") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:4] Set("SIP/keyyo.net-00005a22", "XIVO_INCALL_ID=370") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:5] Set("SIP/keyyo.net-00005a22", "__XIVO_CALLORIGIN=extern") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:6] AGI("SIP/keyyo.net-00005a22", "agi://127.0.0.1/callerid_extend") in new stack
[Oct  3 16:04:23]  agi://127.0.0.1/callerid_extend: AGI handler 'callerid_extend' successfully executed
[Oct  3 16:04:23]     -- <SIP/keyyo.net-00005a22>AGI Script agi://127.0.0.1/callerid_extend completed, returning 0
[Oct  3 16:04:23]     -- Executing [s@did:7] AGI("SIP/keyyo.net-00005a22", "agi://127.0.0.1/in_callerid") in new stack
[Oct  3 16:04:23]  agi://127.0.0.1/in_callerid: AGI handler 'in_callerid' successfully executed
[Oct  3 16:04:23]     -- <SIP/keyyo.net-00005a22>AGI Script agi://127.0.0.1/in_callerid completed, returning 0
[Oct  3 16:04:23]     -- Executing [s@did:8] AGI("SIP/keyyo.net-00005a22", "agi://127.0.0.1/callerid_forphones") in new stack
[Oct  3 16:04:23]  agi://127.0.0.1/callerid_forphones: AGI handler 'callerid_forphones' successfully executed
[Oct  3 16:04:23]     -- <SIP/keyyo.net-00005a22>AGI Script agi://127.0.0.1/callerid_forphones completed, returning 0
[Oct  3 16:04:23]     -- Executing [s@did:9] UserEvent("SIP/keyyo.net-00005a22", "ReverseLookup,CHANNEL: SIP/keyyo.net-00005a22") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:10] Set("SIP/keyyo.net-00005a22", "XIVO_SRCNUM=0xxxxxxxx") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:11] Gosub("SIP/keyyo.net-00005a22", "xivo-did_rights_check,s,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-did_rights_check:1] AGI("SIP/keyyo.net-00005a22", "agi://127.0.0.1/did_set_call_rights") in new stack
[Oct  3 16:04:23]  agi://127.0.0.1/did_set_call_rights: AGI handler 'did_set_call_rights' successfully executed
[Oct  3 16:04:23]     -- <SIP/keyyo.net-00005a22>AGI Script agi://127.0.0.1/did_set_call_rights completed, returning 0
[Oct  3 16:04:23]     -- Executing [s@xivo-did_rights_check:2] GotoIf("SIP/keyyo.net-00005a22", "ALLOW?:error,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-did_rights_check:3] GotoIf("SIP/keyyo.net-00005a22", "1?allow,1") in new stack
[Oct  3 16:04:23]     -- Goto (xivo-did_rights_check,allow,1)
[Oct  3 16:04:23]     -- Executing [allow@xivo-did_rights_check:1] NoOp("SIP/keyyo.net-00005a22", "Caller allowed to make call") in new stack
[Oct  3 16:04:23]     -- Executing [allow@xivo-did_rights_check:2] Return("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:12] AGI("SIP/keyyo.net-00005a22", "agi://127.0.0.1/incoming_did_set_features") in new stack
[Oct  3 16:04:23]  agi://127.0.0.1/incoming_did_set_features: AGI handler 'incoming_did_set_features' successfully executed
[Oct  3 16:04:23]     -- <SIP/keyyo.net-00005a22>AGI Script agi://127.0.0.1/incoming_did_set_features completed, returning 0
[Oct  3 16:04:23]     -- Executing [s@did:13] UserEvent("SIP/keyyo.net-00005a22", "Did,XIVO_SRCNUM: 0xxxxxxxx,XIVO_SRCNAME: 33xxxxxxxx,XIVO_EXTENPATTERN: 334xxxxxxxx,CHANNEL: SIP/keyyo.net-00005a22,XIVO_SRCTON: 0,XIVO_SRCRDNIS: ") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:14] CELGenUserEvent("SIP/keyyo.net-00005a22", "XIVO_INCALL") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:15] AGI("SIP/keyyo.net-00005a22", "agi://127.0.0.1/check_schedule") in new stack
[Oct  3 16:04:23]  agi://127.0.0.1/check_schedule: AGI handler 'check_schedule' successfully executed
[Oct  3 16:04:23]     -- <SIP/keyyo.net-00005a22>AGI Script agi://127.0.0.1/check_schedule completed, returning 0
[Oct  3 16:04:23]     -- Executing [s@did:16] GotoIf("SIP/keyyo.net-00005a22", "0?CLOSED,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:17] Gosub("SIP/keyyo.net-00005a22", "xivo-subroutine,s,1()") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-subroutine:1] GotoIf("SIP/keyyo.net-00005a22", "?:nosubroutine") in new stack
[Oct  3 16:04:23]     -- Goto (xivo-subroutine,s,4)
[Oct  3 16:04:23]     -- Executing [s@xivo-subroutine:4] Return("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:18] Gosub("SIP/keyyo.net-00005a22", "xivo-global-subroutine,s,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-global-subroutine:1] GotoIf("SIP/keyyo.net-00005a22", "1?:return") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-global-subroutine:2] GotoIf("SIP/keyyo.net-00005a22", "DID?:return") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-global-subroutine:3] GotoIf("SIP/keyyo.net-00005a22", "xivo-subrgbl-did?:return") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-global-subroutine:4] GotoIf("SIP/keyyo.net-00005a22", "0?:return") in new stack
[Oct  3 16:04:23]     -- Goto (xivo-global-subroutine,s,6)
[Oct  3 16:04:23]     -- Executing [s@xivo-global-subroutine:6] Return("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:23]     -- Executing [s@did:19] Gosub("SIP/keyyo.net-00005a22", "forward,s,1(user,555,)") in new stack
[Oct  3 16:04:23]     -- Executing [s@forward:1] Set("SIP/keyyo.net-00005a22", "XIVO_FWD_ACTION=user") in new stack
[Oct  3 16:04:23]     -- Executing [s@forward:2] GotoIf("SIP/keyyo.net-00005a22", "user?:error,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@forward:3] Set("SIP/keyyo.net-00005a22", "XIVO_FWD_ACTIONARG1=555") in new stack
[Oct  3 16:04:23]     -- Executing [s@forward:4] Set("SIP/keyyo.net-00005a22", "XIVO_FWD_ACTIONARG2=") in new stack
[Oct  3 16:04:23]     -- Executing [s@forward:5] Set("SIP/keyyo.net-00005a22", "__XIVO_FROMGROUP=0") in new stack
[Oct  3 16:04:23]     -- Executing [s@forward:6] Set("SIP/keyyo.net-00005a22", "__XIVO_FROMQUEUE=0") in new stack
[Oct  3 16:04:23]     -- Executing [s@forward:7] Set("SIP/keyyo.net-00005a22", "CALLCOMPLETION(cc_agent_policy)=never") in new stack
[Oct  3 16:04:23]     -- Executing [s@forward:8] Goto("SIP/keyyo.net-00005a22", "user,1") in new stack
[Oct  3 16:04:23]     -- Goto (forward,user,1)
[Oct  3 16:04:23]     -- Executing [user@forward:1] Set("SIP/keyyo.net-00005a22", "XIVO_PRESUBR_FWD_NAME=USER") in new stack
[Oct  3 16:04:23]     -- Executing [user@forward:2] Gosub("SIP/keyyo.net-00005a22", "xivo-fwd-subroutine,s,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-fwd-subroutine:1] Set("SIP/keyyo.net-00005a22", "__XIVO_USERID=") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-fwd-subroutine:2] Return("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:23]     -- Executing [user@forward:3] Gosub("SIP/keyyo.net-00005a22", "user,s,1(555,)") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:1] Set("SIP/keyyo.net-00005a22", "XIVO_DSTID=555") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:2] Set("SIP/keyyo.net-00005a22", "XIVO_DST_EXTEN_ID=") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:3] Set("SIP/keyyo.net-00005a22", "XIVO_PRESUBR_GLOBAL_NAME=USER") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:4] Set("SIP/keyyo.net-00005a22", "CC_EXTEN=334xxxxxxxx") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:5] Set("SIP/keyyo.net-00005a22", "CC_CONTEXT=from-extern") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:6] Set("SIP/keyyo.net-00005a22", "XIVO_SRCNUM=0xxxxxxxx") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:7] Set("SIP/keyyo.net-00005a22", "XIVO_DSTNUM=334xxxxxxxx") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:8] Set("SIP/keyyo.net-00005a22", "XIVO_CONTEXT=from-extern") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:9] Set("SIP/keyyo.net-00005a22", "WAZO_CHANNEL_DIRECTION=to-wazo") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:10] Set("SIP/keyyo.net-00005a22", "__XIVO_CALLORIGIN=extern") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:11] Set("SIP/keyyo.net-00005a22", "__XIVO_FWD_REFERER=user:555") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:12] UserEvent("SIP/keyyo.net-00005a22", "User,CHANNEL: SIP/keyyo.net-00005a22,XIVO_USERID: ,XIVO_SRCNUM: 0xxxxxxxx,XIVO_CALLORIGIN: extern,XIVO_DSTID: 555") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:13] GotoIf("SIP/keyyo.net-00005a22", "?:noblindxfer") in new stack
[Oct  3 16:04:23]     -- Goto (user,s,15)
[Oct  3 16:04:23]     -- Executing [s@user:15] Set("SIP/keyyo.net-00005a22", "XIVO_FWD_REFERER_TYPE=user") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:16] Set("SIP/keyyo.net-00005a22", "XIVO_REAL_FROMGROUP=0") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:17] Set("SIP/keyyo.net-00005a22", "XIVO_REAL_FROMQUEUE=0") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:18] AGI("SIP/keyyo.net-00005a22", "agi://127.0.0.1/incoming_user_set_features") in new stack
[Oct  3 16:04:23]  agi://127.0.0.1/incoming_user_set_features: AGI handler 'incoming_user_set_features' successfully executed
[Oct  3 16:04:23]     -- <SIP/keyyo.net-00005a22>AGI Script agi://127.0.0.1/incoming_user_set_features completed, returning 0
[Oct  3 16:04:23]     -- Executing [s@user:19] Gosub("SIP/keyyo.net-00005a22", "wazo-setup-userevent-dial-echo,s,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@wazo-setup-userevent-dial-echo:1] GotoIf("SIP/keyyo.net-00005a22", "0?:return") in new stack
[Oct  3 16:04:23]     -- Goto (wazo-setup-userevent-dial-echo,s,3)
[Oct  3 16:04:23]     -- Executing [s@wazo-setup-userevent-dial-echo:3] Return("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:20] NoOp("SIP/keyyo.net-00005a22", "filename call recording: none") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:21] AGI("SIP/keyyo.net-00005a22", "agi://127.0.0.1/check_schedule") in new stack
[Oct  3 16:04:23]  agi://127.0.0.1/check_schedule: AGI handler 'check_schedule' successfully executed
[Oct  3 16:04:23]     -- <SIP/keyyo.net-00005a22>AGI Script agi://127.0.0.1/check_schedule completed, returning 0
[Oct  3 16:04:23]     -- Executing [s@user:22] GotoIf("SIP/keyyo.net-00005a22", "0?CLOSED,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:23] Gosub("SIP/keyyo.net-00005a22", "xivo-ring_type_set,s,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-ring_type_set:1] SIPRemoveHeader("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-ring_type_set:2] AGI("SIP/keyyo.net-00005a22", "agi://127.0.0.1/getring") in new stack
[Oct  3 16:04:23]  agi://127.0.0.1/getring: Using the native phone ring tone
[Oct  3 16:04:23]  agi://127.0.0.1/getring: AGI handler 'getring' successfully executed
[Oct  3 16:04:23]     -- <SIP/keyyo.net-00005a22>AGI Script agi://127.0.0.1/getring completed, returning 0
[Oct  3 16:04:23]     -- Executing [s@xivo-ring_type_set:3] GotoIf("SIP/keyyo.net-00005a22", "?:exit") in new stack
[Oct  3 16:04:23]     -- Goto (xivo-ring_type_set,s,8)
[Oct  3 16:04:23]     -- Executing [s@xivo-ring_type_set:8] Return("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:24] Gosub("SIP/keyyo.net-00005a22", "xivo-subroutine,s,1()") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-subroutine:1] GotoIf("SIP/keyyo.net-00005a22", "?:nosubroutine") in new stack
[Oct  3 16:04:23]     -- Goto (xivo-subroutine,s,4)
[Oct  3 16:04:23]     -- Executing [s@xivo-subroutine:4] Return("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:25] Set("SIP/keyyo.net-00005a22", "XIVO_RINGSECONDS=20") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:26] Gosub("SIP/keyyo.net-00005a22", "xivo-user_rights_check,s,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-user_rights_check:1] AGI("SIP/keyyo.net-00005a22", "agi://127.0.0.1/user_set_call_rights") in new stack
[Oct  3 16:04:23]  agi://127.0.0.1/user_set_call_rights: AGI handler 'user_set_call_rights' successfully executed
[Oct  3 16:04:23]     -- <SIP/keyyo.net-00005a22>AGI Script agi://127.0.0.1/user_set_call_rights completed, returning 0
[Oct  3 16:04:23]     -- Executing [s@xivo-user_rights_check:2] GotoIf("SIP/keyyo.net-00005a22", "ALLOW?:error,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-user_rights_check:3] GotoIf("SIP/keyyo.net-00005a22", "1?allow,1") in new stack
[Oct  3 16:04:23]     -- Goto (xivo-user_rights_check,allow,1)
[Oct  3 16:04:23]     -- Executing [allow@xivo-user_rights_check:1] NoOp("SIP/keyyo.net-00005a22", "User allowed to make call") in new stack
[Oct  3 16:04:23]     -- Executing [allow@xivo-user_rights_check:2] Return("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:27] GotoIf("SIP/keyyo.net-00005a22", "0?dial_from_queue,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:28] GotoIf("SIP/keyyo.net-00005a22", "0?xivo-user_callfilter,s,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:29] GotoIf("SIP/keyyo.net-00005a22", "?:31") in new stack
[Oct  3 16:04:23]     -- Goto (user,s,31)
[Oct  3 16:04:23]     -- Executing [s@user:31] GotoIf("SIP/keyyo.net-00005a22", "0?DND,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:32] GotoIf("SIP/keyyo.net-00005a22", "0?UNC,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:33] GotoIf("SIP/keyyo.net-00005a22", "0?dial_from_group,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:34] GotoIf("SIP/keyyo.net-00005a22", "0?BUSY,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:35] Set("SIP/keyyo.net-00005a22", "OUTBOUND_GROUP_ONCE=555@XIVO_USER") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:36] Gosub("SIP/keyyo.net-00005a22", "xivo-connectedline,s,1(334xxxxxxxx,Nicolas TORIKIAN)") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-connectedline:1] NoOp("SIP/keyyo.net-00005a22", "Generic subroutine for connectedline") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-connectedline:2] Set("SIP/keyyo.net-00005a22", "CONNECTEDLINE(all,i)=Nicolas TORIKIAN <334xxxxxxxx>") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-connectedline:3] Return("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:37] Gosub("SIP/keyyo.net-00005a22", "xivo-global-subroutine,s,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-global-subroutine:1] GotoIf("SIP/keyyo.net-00005a22", "1?:return") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-global-subroutine:2] GotoIf("SIP/keyyo.net-00005a22", "USER?:return") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-global-subroutine:3] GotoIf("SIP/keyyo.net-00005a22", "xivo-subrgbl-user?:return") in new stack
[Oct  3 16:04:23]     -- Executing [s@xivo-global-subroutine:4] GotoIf("SIP/keyyo.net-00005a22", "0?:return") in new stack
[Oct  3 16:04:23]     -- Goto (xivo-global-subroutine,s,6)
[Oct  3 16:04:23]     -- Executing [s@xivo-global-subroutine:6] Return("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:38] Gosub("SIP/keyyo.net-00005a22", "originate-caller-id,s,1") in new stack
[Oct  3 16:04:23]     -- Executing [s@originate-caller-id:1] GotoIf("SIP/keyyo.net-00005a22", "0?:name") in new stack
[Oct  3 16:04:23]     -- Goto (originate-caller-id,s,3)
[Oct  3 16:04:23]     -- Executing [s@originate-caller-id:3] GotoIf("SIP/keyyo.net-00005a22", "0?:fix") in new stack
[Oct  3 16:04:23]     -- Goto (originate-caller-id,s,5)
[Oct  3 16:04:23]     -- Executing [s@originate-caller-id:5] GotoIf("SIP/keyyo.net-00005a22", "?:end") in new stack
[Oct  3 16:04:23]     -- Goto (originate-caller-id,s,9)
[Oct  3 16:04:23]     -- Executing [s@originate-caller-id:9] Return("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:23]     -- Executing [s@user:39] Dial("SIP/keyyo.net-00005a22", "SIP/neo14d25,20,ht") in new stack
[Oct  3 16:04:23]   == Using SIP RTP CoS mark 5
[Oct  3 16:04:23]     -- Called SIP/neo14d25
[Oct  3 16:04:23]     -- SIP/neo14d25-00005a23 is ringing
[Oct  3 16:04:24]     -- SIP/neo14d25-00005a23 is ringing
[Oct  3 16:04:24]   == Spawn extension (user, s, 39) exited non-zero on 'SIP/keyyo.net-00005a22'
[Oct  3 16:04:24]     -- Executing [h@user:1] NoOp("SIP/keyyo.net-00005a22", " ###TEST CANAL / APPELANT 0xxxxxxxx / APPELE : 334xxxxxxxx ###") in new stack
[Oct  3 16:04:24]     -- Executing [h@user:2] GotoIf("SIP/keyyo.net-00005a22", "0?return") in new stack
[Oct  3 16:04:24]     -- Executing [h@user:3] GotoIf("SIP/keyyo.net-00005a22", "0?return") in new stack
[Oct  3 16:04:24]     -- Executing [h@user:4] GotoIf("SIP/keyyo.net-00005a22", "0?return") in new stack
[Oct  3 16:04:24]     -- Executing [h@user:5] GotoIf("SIP/keyyo.net-00005a22", "0?return") in new stack
[Oct  3 16:04:24]     -- Executing [h@user:6] GotoIf("SIP/keyyo.net-00005a22", "0?return") in new stack
[Oct  3 16:04:24]     -- Executing [h@user:7] GotoIf("SIP/keyyo.net-00005a22", "0?return") in new stack
[Oct  3 16:04:24]     -- Executing [h@user:8] GotoIf("SIP/keyyo.net-00005a22", "0?return") in new stack
[Oct  3 16:04:24]     -- Executing [h@user:9] GotoIf("SIP/keyyo.net-00005a22", "0?return") in new stack
[Oct  3 16:04:24]     -- Executing [h@user:10] GotoIf("SIP/keyyo.net-00005a22", "1?return") in new stack
[Oct  3 16:04:24]     -- Goto (user,h,70)
[Oct  3 16:04:24]     -- Executing [h@user:70] Return("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:24]     -- Executing [user@forward:4] Return("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:24]     -- Executing [s@did:20] Hangup("SIP/keyyo.net-00005a22", "") in new stack
[Oct  3 16:04:24]   == Spawn extension (did, s, 20) exited non-zero on 'SIP/keyyo.net-00005a22'

#4 Updated by Sébastien Duthil 2 months ago

Peux-tu activer le debug sur le serveur d'AGI:

  • asterisk -rx 'agi set debug on'
  • echo "debug: true" > /etc/xivo-agid/conf.d/0-debug.yml

Puis refaire l'appel et nous donner:

  • /var/log/asterisk/full
  • /var/log/xivo-agid.log

#5 Updated by Nico JB 2 months ago

et voici :

[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [33xxxxxxxx@from-extern:1] Set("SIP/keyyo.net-00005c55", "XIVO_BASE_CONTEXT=from-extern") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [33xxxxxxxx@from-extern:2] Set("SIP/keyyo.net-00005c55", "XIVO_BASE_EXTEN=33xxxxxxxx") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [33xxxxxxxx@from-extern:3] GotoIf("SIP/keyyo.net-00005c55", "?:action") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (from-extern,33xxxxxxxx,5)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [33xxxxxxxx@from-extern:5] Gosub("SIP/keyyo.net-00005c55", "did,s,1(370,)") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:1] Set("SIP/keyyo.net-00005c55", "XIVO_DSTNUM=33xxxxxxxx") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:2] Set("SIP/keyyo.net-00005c55", "XIVO_CONTEXT=from-extern") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:3] Set("SIP/keyyo.net-00005c55", "XIVO_PRESUBR_GLOBAL_NAME=DID") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:4] Set("SIP/keyyo.net-00005c55", "XIVO_INCALL_ID=370") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:5] Set("SIP/keyyo.net-00005c55", "__XIVO_CALLORIGIN=extern") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:6] AGI("SIP/keyyo.net-00005c55", "agi://127.0.0.1/callerid_extend") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network: yes
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network_script: callerid_extend
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_request: agi://127.0.0.1/callerid_extend
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_channel: SIP/keyyo.net-00005c55
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_language: fr_FR
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_type: SIP
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_uniqueid: 1538639328.23968
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_version: 15.2.2
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callerid: +33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_calleridname: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingpres: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingani2: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callington: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingtns: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_dnid: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_rdnis: unknown
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_context: did
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_extension: s
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_priority: 6
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_enhanced: 0.0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_accountcode:
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_threadid: 140049953982208
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >>
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_SRCTON" "0" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << VERBOSE "AGI handler 'callerid_extend' successfully executed" 1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: agi://127.0.0.1/callerid_extend: AGI handler 'callerid_extend' successfully executed
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Script agi://127.0.0.1/callerid_extend completed, returning 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:7] AGI("SIP/keyyo.net-00005c55", "agi://127.0.0.1/in_callerid") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network: yes
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network_script: in_callerid
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_request: agi://127.0.0.1/in_callerid
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_channel: SIP/keyyo.net-00005c55
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_language: fr_FR
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_type: SIP
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_uniqueid: 1538639328.23968
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_version: 15.2.2
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callerid: +33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_calleridname: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingpres: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingani2: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callington: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingtns: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_dnid: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_rdnis: unknown
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_context: did
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_extension: s
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_priority: 7
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_enhanced: 0.0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_accountcode:
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_threadid: 140049953982208
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >>
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "CALLERID(num)" "0xxxxxxxx" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << VERBOSE "AGI handler 'in_callerid' successfully executed" 1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: agi://127.0.0.1/in_callerid: AGI handler 'in_callerid' successfully executed
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Script agi://127.0.0.1/in_callerid completed, returning 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:8] AGI("SIP/keyyo.net-00005c55", "agi://127.0.0.1/callerid_forphones") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network: yes
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network_script: callerid_forphones
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_request: agi://127.0.0.1/callerid_forphones
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_channel: SIP/keyyo.net-00005c55
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_language: fr_FR
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_type: SIP
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_uniqueid: 1538639328.23968
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_version: 15.2.2
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callerid: 0xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_calleridname: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingpres: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingani2: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callington: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingtns: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_dnid: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_rdnis: unknown
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_context: did
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_extension: s
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_priority: 8
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_enhanced: 0.0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_accountcode:
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_threadid: 140049953982208
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >>
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << VERBOSE "AGI handler 'callerid_forphones' successfully executed" 1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: agi://127.0.0.1/callerid_forphones: AGI handler 'callerid_forphones' successfully executed
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Script agi://127.0.0.1/callerid_forphones completed, returning 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:9] UserEvent("SIP/keyyo.net-00005c55", "ReverseLookup,CHANNEL: SIP/keyyo.net-00005c55") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:10] Set("SIP/keyyo.net-00005c55", "XIVO_SRCNUM=0xxxxxxxx") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:11] Gosub("SIP/keyyo.net-00005c55", "xivo-did_rights_check,s,1") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-did_rights_check:1] AGI("SIP/keyyo.net-00005c55", "agi://127.0.0.1/did_set_call_rights") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network: yes
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network_script: did_set_call_rights
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_request: agi://127.0.0.1/did_set_call_rights
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_channel: SIP/keyyo.net-00005c55
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_language: fr_FR
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_type: SIP
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_uniqueid: 1538639328.23968
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_version: 15.2.2
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callerid: 0xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_calleridname: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingpres: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingani2: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callington: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingtns: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_dnid: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_rdnis: unknown
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_context: xivo-did_rights_check
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_extension: s
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_priority: 1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_enhanced: 0.0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_accountcode:
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_threadid: 140049953982208
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >>
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_SRCNUM" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (0xxxxxxxx)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_INCALL_ID" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (370)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_AUTHORIZATION" "ALLOW" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << VERBOSE "AGI handler 'did_set_call_rights' successfully executed" 1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: agi://127.0.0.1/did_set_call_rights: AGI handler 'did_set_call_rights' successfully executed
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Script agi://127.0.0.1/did_set_call_rights completed, returning 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-did_rights_check:2] GotoIf("SIP/keyyo.net-00005c55", "ALLOW?:error,1") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-did_rights_check:3] GotoIf("SIP/keyyo.net-00005c55", "1?allow,1") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (xivo-did_rights_check,allow,1)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [allow@xivo-did_rights_check:1] NoOp("SIP/keyyo.net-00005c55", "Caller allowed to make call") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [allow@xivo-did_rights_check:2] Return("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:12] AGI("SIP/keyyo.net-00005c55", "agi://127.0.0.1/incoming_did_set_features") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network: yes
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network_script: incoming_did_set_features
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_request: agi://127.0.0.1/incoming_did_set_features
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_channel: SIP/keyyo.net-00005c55
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_language: fr_FR
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_type: SIP
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_uniqueid: 1538639328.23968
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_version: 15.2.2
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callerid: 0xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_calleridname: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingpres: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingani2: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callington: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingtns: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_dnid: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_rdnis: unknown
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_context: did
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_extension: s
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_priority: 12
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_enhanced: 0.0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_accountcode:
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_threadid: 140049953982208
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >>
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_INCALL_ID" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (370)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_DIDPREPROCESS_SUBROUTINE" "" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_EXTENPATTERN" "33xxxxxxxx" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_PATH" "incall" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_PATH_ID" "370" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_REAL_CONTEXT" "from-extern" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_REAL_NUMBER" "33xxxxxxxx" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_INCALL_ANSWER_ACTION" "user" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_INCALL_ANSWER_ISDA" "1" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_INCALL_ANSWER_ACTIONARG1" "555" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_INCALL_ANSWER_ACTIONARG2" "" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << VERBOSE "AGI handler 'incoming_did_set_features' successfully executed" 1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: agi://127.0.0.1/incoming_did_set_features: AGI handler 'incoming_did_set_features' successfully executed
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Script agi://127.0.0.1/incoming_did_set_features completed, returning 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:13] UserEvent("SIP/keyyo.net-00005c55", "Did,XIVO_SRCNUM: 0xxxxxxxx,XIVO_SRCNAME: 33xxxxxxxx,XIVO_EXTENPATTERN: 33xxxxxxxx,CHANNEL: SIP/keyyo.net-00005c55,XIVO_SRCTON: 0,XIVO_SRCRDNIS: ") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:14] CELGenUserEvent("SIP/keyyo.net-00005c55", "XIVO_INCALL") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:15] AGI("SIP/keyyo.net-00005c55", "agi://127.0.0.1/check_schedule") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network: yes
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network_script: check_schedule
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_request: agi://127.0.0.1/check_schedule
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_channel: SIP/keyyo.net-00005c55
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_language: fr_FR
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_type: SIP
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_uniqueid: 1538639328.23968
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_version: 15.2.2
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callerid: 0xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_calleridname: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingpres: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingani2: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callington: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingtns: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_dnid: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_rdnis: unknown
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_context: did
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_extension: s
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_priority: 15
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_enhanced: 0.0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_accountcode:
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_threadid: 140049953982208
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >>
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_PATH" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (incall)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_PATH_ID" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (370)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_SCHEDULE_STATUS" "opened" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_PATH" "" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << VERBOSE "AGI handler 'check_schedule' successfully executed" 1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: agi://127.0.0.1/check_schedule: AGI handler 'check_schedule' successfully executed
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Script agi://127.0.0.1/check_schedule completed, returning 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:16] GotoIf("SIP/keyyo.net-00005c55", "0?CLOSED,1") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:17] Gosub("SIP/keyyo.net-00005c55", "xivo-subroutine,s,1()") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-subroutine:1] GotoIf("SIP/keyyo.net-00005c55", "?:nosubroutine") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (xivo-subroutine,s,4)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-subroutine:4] Return("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:18] Gosub("SIP/keyyo.net-00005c55", "xivo-global-subroutine,s,1") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-global-subroutine:1] GotoIf("SIP/keyyo.net-00005c55", "1?:return") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-global-subroutine:2] GotoIf("SIP/keyyo.net-00005c55", "DID?:return") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-global-subroutine:3] GotoIf("SIP/keyyo.net-00005c55", "xivo-subrgbl-did?:return") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-global-subroutine:4] GotoIf("SIP/keyyo.net-00005c55", "0?:return") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (xivo-global-subroutine,s,6)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-global-subroutine:6] Return("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:19] Gosub("SIP/keyyo.net-00005c55", "forward,s,1(user,555,)") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@forward:1] Set("SIP/keyyo.net-00005c55", "XIVO_FWD_ACTION=user") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@forward:2] GotoIf("SIP/keyyo.net-00005c55", "user?:error,1") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@forward:3] Set("SIP/keyyo.net-00005c55", "XIVO_FWD_ACTIONARG1=555") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@forward:4] Set("SIP/keyyo.net-00005c55", "XIVO_FWD_ACTIONARG2=") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@forward:5] Set("SIP/keyyo.net-00005c55", "__XIVO_FROMGROUP=0") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@forward:6] Set("SIP/keyyo.net-00005c55", "__XIVO_FROMQUEUE=0") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@forward:7] Set("SIP/keyyo.net-00005c55", "CALLCOMPLETION(cc_agent_policy)=never") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@forward:8] Goto("SIP/keyyo.net-00005c55", "user,1") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (forward,user,1)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [user@forward:1] Set("SIP/keyyo.net-00005c55", "XIVO_PRESUBR_FWD_NAME=USER") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [user@forward:2] Gosub("SIP/keyyo.net-00005c55", "xivo-fwd-subroutine,s,1") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-fwd-subroutine:1] Set("SIP/keyyo.net-00005c55", "__XIVO_USERID=") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-fwd-subroutine:2] Return("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [user@forward:3] Gosub("SIP/keyyo.net-00005c55", "user,s,1(555,)") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:1] Set("SIP/keyyo.net-00005c55", "XIVO_DSTID=555") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:2] Set("SIP/keyyo.net-00005c55", "XIVO_DST_EXTEN_ID=") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:3] Set("SIP/keyyo.net-00005c55", "XIVO_PRESUBR_GLOBAL_NAME=USER") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:4] Set("SIP/keyyo.net-00005c55", "CC_EXTEN=33xxxxxxxx") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:5] Set("SIP/keyyo.net-00005c55", "CC_CONTEXT=from-extern") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:6] Set("SIP/keyyo.net-00005c55", "XIVO_SRCNUM=0xxxxxxxx") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:7] Set("SIP/keyyo.net-00005c55", "XIVO_DSTNUM=33xxxxxxxx") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:8] Set("SIP/keyyo.net-00005c55", "XIVO_CONTEXT=from-extern") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:9] Set("SIP/keyyo.net-00005c55", "WAZO_CHANNEL_DIRECTION=to-wazo") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:10] Set("SIP/keyyo.net-00005c55", "__XIVO_CALLORIGIN=extern") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:11] Set("SIP/keyyo.net-00005c55", "__XIVO_FWD_REFERER=user:555") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:12] UserEvent("SIP/keyyo.net-00005c55", "User,CHANNEL: SIP/keyyo.net-00005c55,XIVO_USERID: ,XIVO_SRCNUM: 0xxxxxxxx,XIVO_CALLORIGIN: extern,XIVO_DSTID: 555") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:13] GotoIf("SIP/keyyo.net-00005c55", "?:noblindxfer") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (user,s,15)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:15] Set("SIP/keyyo.net-00005c55", "XIVO_FWD_REFERER_TYPE=user") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:16] Set("SIP/keyyo.net-00005c55", "XIVO_REAL_FROMGROUP=0") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:17] Set("SIP/keyyo.net-00005c55", "XIVO_REAL_FROMQUEUE=0") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:18] AGI("SIP/keyyo.net-00005c55", "agi://127.0.0.1/incoming_user_set_features") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network: yes
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network_script: incoming_user_set_features
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_request: agi://127.0.0.1/incoming_user_set_features
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_channel: SIP/keyyo.net-00005c55
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_language: fr_FR
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_type: SIP
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_uniqueid: 1538639328.23968
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_version: 15.2.2
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callerid: 0xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_calleridname: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingpres: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingani2: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callington: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingtns: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_dnid: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_rdnis: unknown
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_context: user
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_extension: s
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_priority: 18
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_enhanced: 0.0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_accountcode:
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_threadid: 140049953982208
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >>
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_USERID" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 ()
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_DSTID" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (555)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_DST_EXTEN_ID" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 ()
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_CALLORIGIN" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (extern)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_SRCNUM" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (0xxxxxxxx)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_DSTNUM" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (33xxxxxxxx)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_BASE_CONTEXT" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (from-extern)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_DST_USERNUM" "1108" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_DST_FIRSTNAME" "Nicolas" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_DST_LASTNAME" "TORIKIAN" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_DST_REDIRECTING_NAME" "Nicolas TORIKIAN" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_DST_REDIRECTING_NUM" "1108" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_INTERFACE" "SIP/neo14d25" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_CALLOPTIONS" "ht" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_SIMULTCALLS" "5" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_RINGSECONDS" "20" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_ENABLEDND" "0" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_ENABLEVOICEMAIL" "1" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_MAILBOX" "1100" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_MAILBOX_CONTEXT" "default" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_USEREMAIL" "support365@secureit.fr" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_ENABLEUNC" "0" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_UNC_ACTION" "none" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_UNC_ACTIONARG1" "" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_UNC_ACTIONARG2" "" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_BUSY_ACTION" "group" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_BUSY_ISDA" "1" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_BUSY_ACTIONARG1" "3" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_BUSY_ACTIONARG2" "" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_ENABLEBUSY" "True" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_NOANSWER_ACTION" "group" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_NOANSWER_ISDA" "1" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_NOANSWER_ACTIONARG1" "3" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_NOANSWER_ACTIONARG2" "" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_ENABLERNA" "True" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_CONGESTION_ACTION" "group" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_CONGESTION_ISDA" "1" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_CONGESTION_ACTIONARG1" "3" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_CONGESTION_ACTIONARG2" "" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_CHANUNAVAIL_ACTION" "group" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_CHANUNAVAIL_ISDA" "1" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_CHANUNAVAIL_ACTIONARG1" "3" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_FWD_USER_CHANUNAVAIL_ACTIONARG2" "" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "CHANNEL(musicclass)" "secureit" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_CALLRECORDFILE" "" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_USERPREPROCESS_SUBROUTINE" "" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_MOBILEPHONENUMBER" "" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_MAILBOX_LANGUAGE" "fr_FR" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_PATH" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 ()
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_PATH" "user" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_PATH_ID" "555" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << VERBOSE "AGI handler 'incoming_user_set_features' successfully executed" 1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: agi://127.0.0.1/incoming_user_set_features: AGI handler 'incoming_user_set_features' successfully executed
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Script agi://127.0.0.1/incoming_user_set_features completed, returning 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:19] Gosub("SIP/keyyo.net-00005c55", "wazo-setup-userevent-dial-echo,s,1") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@wazo-setup-userevent-dial-echo:1] GotoIf("SIP/keyyo.net-00005c55", "0?:return") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (wazo-setup-userevent-dial-echo,s,3)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@wazo-setup-userevent-dial-echo:3] Return("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:20] NoOp("SIP/keyyo.net-00005c55", "filename call recording: none") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:21] AGI("SIP/keyyo.net-00005c55", "agi://127.0.0.1/check_schedule") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network: yes
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network_script: check_schedule
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_request: agi://127.0.0.1/check_schedule
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_channel: SIP/keyyo.net-00005c55
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_language: fr_FR
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_type: SIP
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_uniqueid: 1538639328.23968
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_version: 15.2.2
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callerid: 0xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_calleridname: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingpres: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingani2: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callington: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingtns: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_dnid: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_rdnis: unknown
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_context: user
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_extension: s
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_priority: 21
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_enhanced: 0.0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_accountcode:
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_threadid: 140049953982208
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >>
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_PATH" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (user)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_PATH_ID" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (555)
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_SCHEDULE_STATUS" "opened" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_PATH" "" 
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << VERBOSE "AGI handler 'check_schedule' successfully executed" 1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: agi://127.0.0.1/check_schedule: AGI handler 'check_schedule' successfully executed
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Script agi://127.0.0.1/check_schedule completed, returning 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:22] GotoIf("SIP/keyyo.net-00005c55", "0?CLOSED,1") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:23] Gosub("SIP/keyyo.net-00005c55", "xivo-ring_type_set,s,1") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-ring_type_set:1] SIPRemoveHeader("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-ring_type_set:2] AGI("SIP/keyyo.net-00005c55", "agi://127.0.0.1/getring") in new stack
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network: yes
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network_script: getring
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_request: agi://127.0.0.1/getring
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_channel: SIP/keyyo.net-00005c55
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_language: fr_FR
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_type: SIP
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_uniqueid: 1538639328.23968
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_version: 15.2.2
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callerid: 0xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_calleridname: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingpres: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingani2: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callington: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingtns: 0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_dnid: 33xxxxxxxx
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_rdnis: unknown
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_context: xivo-ring_type_set
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_extension: s
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_priority: 2
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_enhanced: 0.0
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_accountcode:
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_threadid: 140049953982208
[Oct  4 09:48:48] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >>
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_REAL_NUMBER" 
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (33xxxxxxxx)
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_REAL_CONTEXT" 
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (from-extern)
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_CALLORIGIN" 
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (extern)
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_FWD_REFERER" 
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (user:555)
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_CALLFORWARDED" 
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=0
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_RINGTYPE" "" 
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << VERBOSE "Using the native phone ring tone" 1
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: agi://127.0.0.1/getring: Using the native phone ring tone
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << VERBOSE "AGI handler 'getring' successfully executed" 1
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: agi://127.0.0.1/getring: AGI handler 'getring' successfully executed
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Script agi://127.0.0.1/getring completed, returning 0
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-ring_type_set:3] GotoIf("SIP/keyyo.net-00005c55", "?:exit") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (xivo-ring_type_set,s,8)
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-ring_type_set:8] Return("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:24] Gosub("SIP/keyyo.net-00005c55", "xivo-subroutine,s,1()") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-subroutine:1] GotoIf("SIP/keyyo.net-00005c55", "?:nosubroutine") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (xivo-subroutine,s,4)
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-subroutine:4] Return("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:25] Set("SIP/keyyo.net-00005c55", "XIVO_RINGSECONDS=20") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:26] Gosub("SIP/keyyo.net-00005c55", "xivo-user_rights_check,s,1") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-user_rights_check:1] AGI("SIP/keyyo.net-00005c55", "agi://127.0.0.1/user_set_call_rights") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network: yes
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: AGI Tx >> agi_network_script: user_set_call_rights
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_request: agi://127.0.0.1/user_set_call_rights
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_channel: SIP/keyyo.net-00005c55
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_language: fr_FR
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_type: SIP
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_uniqueid: 1538639328.23968
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_version: 15.2.2
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callerid: 0xxxxxxxx
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_calleridname: 33xxxxxxxx
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingpres: 0
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingani2: 0
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callington: 0
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_callingtns: 0
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_dnid: 33xxxxxxxx
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_rdnis: unknown
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_context: xivo-user_rights_check
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_extension: s
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_priority: 1
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_enhanced: 0.0
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_accountcode:
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> agi_threadid: 140049953982208
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >>
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_USERID" 
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 ()
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_DSTNUM" 
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1 (33xxxxxxxx)
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << GET VARIABLE "XIVO_OUTCALLID" 
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=0
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << SET VARIABLE "XIVO_AUTHORIZATION" "ALLOW" 
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Rx << VERBOSE "AGI handler 'user_set_call_rights' successfully executed" 1
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: agi://127.0.0.1/user_set_call_rights: AGI handler 'user_set_call_rights' successfully executed
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Tx >> 200 result=1
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] res_agi.c: <SIP/keyyo.net-00005c55>AGI Script agi://127.0.0.1/user_set_call_rights completed, returning 0
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-user_rights_check:2] GotoIf("SIP/keyyo.net-00005c55", "ALLOW?:error,1") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-user_rights_check:3] GotoIf("SIP/keyyo.net-00005c55", "1?allow,1") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (xivo-user_rights_check,allow,1)
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [allow@xivo-user_rights_check:1] NoOp("SIP/keyyo.net-00005c55", "User allowed to make call") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [allow@xivo-user_rights_check:2] Return("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:27] GotoIf("SIP/keyyo.net-00005c55", "0?dial_from_queue,1") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:28] GotoIf("SIP/keyyo.net-00005c55", "0?xivo-user_callfilter,s,1") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:29] GotoIf("SIP/keyyo.net-00005c55", "?:31") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (user,s,31)
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:31] GotoIf("SIP/keyyo.net-00005c55", "0?DND,1") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:32] GotoIf("SIP/keyyo.net-00005c55", "0?UNC,1") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:33] GotoIf("SIP/keyyo.net-00005c55", "0?dial_from_group,1") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:34] GotoIf("SIP/keyyo.net-00005c55", "0?BUSY,1") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:35] Set("SIP/keyyo.net-00005c55", "OUTBOUND_GROUP_ONCE=555@XIVO_USER") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:36] Gosub("SIP/keyyo.net-00005c55", "xivo-connectedline,s,1(33xxxxxxxx,Nicolas TORIKIAN)") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-connectedline:1] NoOp("SIP/keyyo.net-00005c55", "Generic subroutine for connectedline") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-connectedline:2] Set("SIP/keyyo.net-00005c55", "CONNECTEDLINE(all,i)=Nicolas TORIKIAN <33xxxxxxxx>") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-connectedline:3] Return("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:37] Gosub("SIP/keyyo.net-00005c55", "xivo-global-subroutine,s,1") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-global-subroutine:1] GotoIf("SIP/keyyo.net-00005c55", "1?:return") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-global-subroutine:2] GotoIf("SIP/keyyo.net-00005c55", "USER?:return") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-global-subroutine:3] GotoIf("SIP/keyyo.net-00005c55", "xivo-subrgbl-user?:return") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-global-subroutine:4] GotoIf("SIP/keyyo.net-00005c55", "0?:return") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (xivo-global-subroutine,s,6)
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@xivo-global-subroutine:6] Return("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:38] Gosub("SIP/keyyo.net-00005c55", "originate-caller-id,s,1") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@originate-caller-id:1] GotoIf("SIP/keyyo.net-00005c55", "0?:name") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (originate-caller-id,s,3)
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@originate-caller-id:3] GotoIf("SIP/keyyo.net-00005c55", "0?:fix") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (originate-caller-id,s,5)
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@originate-caller-id:5] GotoIf("SIP/keyyo.net-00005c55", "?:end") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (originate-caller-id,s,9)
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@originate-caller-id:9] Return("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] pbx.c: Executing [s@user:39] Dial("SIP/keyyo.net-00005c55", "SIP/neo14d25,20,ht") in new stack
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] netsock2.c: Using SIP RTP CoS mark 5
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] app_dial.c: Called SIP/neo14d25
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] app_dial.c: SIP/neo14d25-00005c56 is ringing
[Oct  4 09:48:49] VERBOSE[3172][C-00002644] app_dial.c: SIP/neo14d25-00005c56 is ringing
[Oct  4 09:48:50] VERBOSE[3172][C-00002644] app_dial.c: SIP/neo14d25-00005c56 is ringing
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Spawn extension (user, s, 39) exited non-zero on 'SIP/keyyo.net-00005c55'
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Executing [h@user:1] NoOp("SIP/keyyo.net-00005c55", " ###TEST CANAL / APPELANT 0xxxxxxxx / APPELE : 33xxxxxxxx ###") in new stack
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Executing [h@user:2] GotoIf("SIP/keyyo.net-00005c55", "0?return") in new stack
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Executing [h@user:3] GotoIf("SIP/keyyo.net-00005c55", "0?return") in new stack
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Executing [h@user:4] GotoIf("SIP/keyyo.net-00005c55", "0?return") in new stack
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Executing [h@user:5] GotoIf("SIP/keyyo.net-00005c55", "0?return") in new stack
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Executing [h@user:6] GotoIf("SIP/keyyo.net-00005c55", "0?return") in new stack
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Executing [h@user:7] GotoIf("SIP/keyyo.net-00005c55", "0?return") in new stack
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Executing [h@user:8] GotoIf("SIP/keyyo.net-00005c55", "0?return") in new stack
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Executing [h@user:9] GotoIf("SIP/keyyo.net-00005c55", "0?return") in new stack
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Executing [h@user:10] GotoIf("SIP/keyyo.net-00005c55", "1?return") in new stack
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx_builtins.c: Goto (user,h,70)
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Executing [h@user:70] Return("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Executing [user@forward:4] Return("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Executing [s@did:20] Hangup("SIP/keyyo.net-00005c55", "") in new stack
[Oct  4 09:48:51] VERBOSE[3172][C-00002644] pbx.c: Spawn extension (did, s, 20) exited non-zero on 'SIP/keyyo.net-00005c55'

2018-10-04 09:48:44,119 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'outgoing_user_set_features'
2018-10-04 09:48:44,177 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:44,177 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:44,188 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:44,192 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:44,192 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'user_set_call_rights'
2018-10-04 09:48:44,201 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:44,201 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:44,204 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:44,205 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:44,205 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'check_schedule'
2018-10-04 09:48:44,216 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:44,216 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:44,835 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:44,840 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:44,843 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'outgoing_user_set_features'
2018-10-04 09:48:44,896 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:44,896 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:44,908 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:44,908 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:44,909 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'user_set_call_rights'
2018-10-04 09:48:44,917 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:44,917 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:44,923 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:44,926 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:44,926 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'check_schedule'
2018-10-04 09:48:44,942 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:44,942 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:46,483 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:46,484 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:46,485 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'outgoing_user_set_features'
2018-10-04 09:48:46,528 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:46,528 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:46,533 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:46,534 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:46,534 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'user_set_call_rights'
2018-10-04 09:48:46,539 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:46,540 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:46,543 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:46,544 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:46,544 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'check_schedule'
2018-10-04 09:48:46,550 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:46,551 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:48,632 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:48,633 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:48,634 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'callerid_extend'
2018-10-04 09:48:48,640 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:48,641 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:48,650 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:48,650 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:48,651 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'in_callerid'
2018-10-04 09:48:48,651 [3038] (DEBUG) (xivo_agid.modules.in_callerid): section `national1`
2018-10-04 09:48:48,651 [3038] (DEBUG) (xivo_agid.modules.in_callerid): pattern `^0[1-9]\d{8}$` does not match `+33xxxxxxxx`
2018-10-04 09:48:48,651 [3038] (DEBUG) (xivo_agid.modules.in_callerid): section `national2`
2018-10-04 09:48:48,651 [3038] (DEBUG) (xivo_agid.modules.in_callerid): pattern `^33\d{9}$` does not match `+33xxxxxxxx`
2018-10-04 09:48:48,652 [3038] (DEBUG) (xivo_agid.modules.in_callerid): section `national3`
2018-10-04 09:48:48,652 [3038] (DEBUG) (xivo_agid.modules.in_callerid): pattern `^\+33\d{9}$` matches `+33xxxxxxxx`
2018-10-04 09:48:48,652 [3038] (DEBUG) (xivo_agid.modules.in_callerid): stripping `3` digits from `+33xxxxxxxx`
2018-10-04 09:48:48,652 [3038] (DEBUG) (xivo_agid.modules.in_callerid): prefixing `xxxxxxxx` with `0`
2018-10-04 09:48:48,655 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:48,655 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:48,657 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:48,657 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:48,658 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'callerid_forphones'
2018-10-04 09:48:48,658 [3038] (DEBUG) (xivo_agid.modules.callerid_forphones): Resolving caller ID: incoming caller ID=33xxxxxxxx 0xxxxxxxx
2018-10-04 09:48:48,659 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:48,659 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:48,663 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:48,663 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:48,664 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'did_set_call_rights'
2018-10-04 09:48:48,668 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:48,668 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:48,683 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:48,684 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:48,684 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'incoming_did_set_features'
2018-10-04 09:48:48,705 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:48,706 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:48,710 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:48,714 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:48,715 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'check_schedule'
2018-10-04 09:48:48,722 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:48,722 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:48,736 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:48,736 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:48,737 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'incoming_user_set_features'
2018-10-04 09:48:48,979 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:48,979 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:48,983 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:48,984 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:48,984 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'check_schedule'
2018-10-04 09:48:48,993 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:48,994 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:48,996 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:48,997 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:48,997 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'getring'
2018-10-04 09:48:49,006 [3038] (DEBUG) (xivo_agid.modules.getring): Ring type available sections: "['number', 'aastra', 'cisco', 'linksys', 'snom', 'thomson', 'yealink']" 
2018-10-04 09:48:49,007 [3038] (DEBUG) (xivo_agid.modules.getring): Ring type section: "None" 
2018-10-04 09:48:49,007 [3038] (DEBUG) (xivo_agid.modules.getring): Ring type context: "from-extern" 
2018-10-04 09:48:49,007 [3038] (DEBUG) (xivo_agid.modules.getring): Ring type exception
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/xivo_agid/modules/getring.py", line 55, in getring
    section = CONFIG_PARSER.get('number', "@%s" % context)
  File "/usr/lib/python2.7/ConfigParser.py", line 340, in get
    raise NoOptionError(option, section)
NoOptionError: No option '@from-extern' in section: 'number'
2018-10-04 09:48:49,011 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:49,011 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:49,016 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:49,017 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:49,017 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'user_set_call_rights'
2018-10-04 09:48:49,021 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:49,022 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:58,870 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:58,871 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:58,872 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'outgoing_user_set_features'
2018-10-04 09:48:58,922 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:58,922 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:58,932 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:58,936 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:58,936 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'user_set_call_rights'
2018-10-04 09:48:58,948 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:58,948 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refilled with connection
2018-10-04 09:48:58,951 [3038] (DEBUG) (xivo_agid.agid): handling request
2018-10-04 09:48:58,969 [3038] (DEBUG) (xivo_agid.agid): acquiring connection: got connection from pool
2018-10-04 09:48:58,969 [3038] (DEBUG) (xivo_agid.agid): delegating request handling 'check_schedule'
2018-10-04 09:48:58,979 [3038] (DEBUG) (xivo_agid.agid): request successfully handled
2018-10-04 09:48:58,979 [3038] (DEBUG) (xivo_agid.agid): releasing connection: pool not full, refill

Visiblement, il y a une erreur dans un fichier python :

Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/xivo_agid/modules/getring.py", line 55, in getring
    section = CONFIG_PARSER.get('number', "@%s" % context)
  File "/usr/lib/python2.7/ConfigParser.py", line 340, in get
    raise NoOptionError(option, section)
NoOptionError: No option '@from-extern' in section: 'number'

#6 Updated by Pascal Cadotte-Michaud 2 months ago

Bonjour,

le problème vient du fait que le caller id name et le caller id number reçu de l'opérateur sont différent. L'AGI compare les deux et comme ce n'est pas la même valeur le reverse lookup ne se fait pas pour éviter d'effacer un caller id name fourni par l'opérateur.

Dans ton cas le caller id number est +33XXX et le caller id name est 33XXX

Je te propose donc d'ajouter un nouveau contexte entrant qui enlève la + au début du caller id number.

Dans l'interface web dans contexte ajoute un nouveau context entrant.

Ensuite dans la section fichiers de configuration ajoute

[patate]
exten = _X.,1,NoOp(${CALLERID(num)} ${CALLERID(name)})
same = n,Set(CALLERID(num)=${REPLACE(CALLERID(num),+,)})
same = n,goto(from-extern,${EXTEN},1)
same = n,hangup

dans mon exemple, tu peux remplacer patate par le nom de ton nouveau context entrant.

Finalement, tu peux aller dans ton trunk et remplacer le contexte par ton nouveau contexte entrant.

Puisqu'il n'y aura plus de + au début du callerid number tu devras modifier ton /etc/xivo/asterisk/xivo_in_callerid.conf pour que la même règle soit appliquer quand il n'y a pas de + au début du numéro.

#7 Updated by Nico JB 2 months ago

Bonjour,

Ok ça fonctionne...
C'est parfait.

J'ai demandé a Keyyo de comprendre pourquoi ils envoient le + maintenant alors qu'il n'était pas envoyé il y a 2 mois. J'ai aussi demandé de l'enlever car j'ai pas envie d'avoir a reconfigurer la totalité de mes ipbx...

Par contre, j'ai un certain nombre de client dans cette conf, ne serait-il pas possible d'avoir une manipulation plus simple : par exemple, juste toucher au dialplan et non a avoir à créer un contexte etc etc...

L'idéal serait d'avoir juste à ajouter cela :

[from-extern]
exten = _X.,1,NoOp(${CALLERID(num)} ${CALLERID(name)})
same = n,Set(CALLERID(num)=${REPLACE(CALLERID(num),+,)})
same = n,goto(from-extern,${EXTEN},1)
same = n,hangup

Cela ne fonctionne pas...

#8 Updated by Sébastien Duthil 2 months ago

En quelle version de Wazo étais-tu avant la mise à jour?

#9 Updated by Nico JB 2 months ago

plusieurs versions :
17.02
16.08

#10 Updated by Nico JB 2 months ago

Bonjour,
Voici la réponse de Keyyo :

Après plusieurs échanges en interne concernant cette problématique, nous n'allons pas faire de retour arrière.
Ces modifications de préfixe ont été appliquées afin de répondre aux conformités protocolaires.
Il vous faut donc configurer sur vos équipements les deux préfixes suivant afin que l'ensemble des appels soient correctement traités par vos IPBX.
+33*********
33*********

On ne pourrait pas appliquer un patch sur xivo-dird pour comparer avec et sans le + ?

#11 Updated by Sébastien Duthil about 1 month ago

Voilà un patch pour déclencher la recherche inverse à chaque appel. Pour l'appliquer:

patch -p1 -d /usr/lib/python2.7/dist-packages/ < /tmp/always-reverse-lookup.patch
systemctl restart xivo-agid

Pour le retirer:

patch -R -p1 -d /usr/lib/python2.7/dist-packages/ < /tmp/always-reverse-lookup.patch
systemctl restart xivo-agid

Also available in: Atom PDF