Auto destruct message rasied in console when calls send to queue

hello dear all
sometimes (almost at noon,11:30 till 13:30, my country pstn peak of calls ) when my concurrent calls reach to 70 or more , i get this error in console :

[Jul 14 11:25:29] WARNING[27838] chan_sip.c: Autodestruct on dialog 'isbcaviklvkr6kkgdgfgs6arfvhvhdql6iqk@SoftX3000' with owner SIP/10.1.10.86-0004ca22 in place (Method: BYE). Rescheduling destruction for 10000 ms

i think “SoftX3000” is Psnt SBC model.
i have a sip trunk with PSTN.
when calls come to asterisk, first an ivr file plays and then with press 0 , calls send to queue.
ivr file plays but with press 0 calls hang (instead of sending to queue) and then above error appears in console for that call.
i think queue don’t works fine when concurrent calls increases or maybe there is another problem:

i call queue with : Dial(LOCAL/8082@from-internal)

[from-interal]
include => ext-queue

[ext-queue]
exten => 8082,1,GoSub(from-queue,${EXTEN},1)

[from-queue]
exten => _XX.,1,set(__qname=${EXTEN})
exten => _XX.,n,set(CDR(userfield)=${callid})
exten => _XX.,n,ExecIf($["${DB(${qname}/queue/record)}"="yes"]?macro(mixmon,${CALLERID(num)},${qname},${CALLERID(dnid)},queue))
exten => _XX.,n,QueueLog(${qname},${UNIQUEID},NONE,DID,${CALLERID(dnid)})
exten => _XX.,n,ExecIf($["${DB(${qname}/queue/timeout)}"=""]?Set(__t=120):Set(__t=${DB(${qname}/queue/timeout)}))
exten => _XX.,n,verbose(penalty: ${QUEUE_MAX_PENALTY})
exten => _XX.,n,Set(QUEUE_MAX_PENALTY=6)
exten => _XX.,n,playback(silent)
exten => _XX.,n,Queue(${qname},cTt,,,${t},i2.php)
exten => _XX.,n,verbose(queue becomes: ${QUEUESTATUS})
exten => _XX.,n,execif($["${QUEUESTATUS}"="TIMEOUT"]?Playback(Voice-253))
exten => _xx.,n,execif($["${queueack}"="yes" & "${DIALSTATUS}"!="ANSWER"]?agi(dial_qconnect_ack-logger.php,${ivrkey},${calllogid},${callid},${uniqi},${actionid},${meta},${DEXTEN},${qname},${app},-7,1652,9101,end)
exten => _XX.,n,set(__qstat=${QUEUESTATUS})
exten => _XX.,n,return()

[queue-agent]
exten => 101,1,Set(__type=SIP)
exten => 101,n,macro(dial-agent,101)


[macro-dial-agent]
exten => s,1,Set(__DEXTEN=${ARG1})
exten => s,n,SIPAddHeader(CallId:${callid})
exten => s,n,SIPAddHeader(CallLogId:${calllogid})
exten => s,n,SIPAddHeader(FlowId:${flowid})
exten => s,n,ExecIf($["${DEVICE_STATE(SIP/${DEXTEN})}"!="NOT_INUSE"]?macroExit())
exten => s,n,dial(${type}/${DEXTEN},12,TtgB(queueack^s^1)M(connect2^${callid}))
exten => s,n,verbose(status of DIAL: ${DIALSTATUS})
exten => s,n,ExecIf($["${DIALSTATUS}"="NOANSWER" | "${DIALSTATUS}"="BUSY"]?agi(dial_qconnect_ack-logger.php,${ivrkey},${calllogid},${callid},${uniqi},${actionid},${meta},${DEXTEN},${qname},${app},-7,1652,9101,end)

queues.conf

[8082]
;announce-frequency = 90
announce-holdtime = no
announce-position = no
autofill = yes
autopause = no
autopausebusy = no
autopausedelay = 0
autopauseunavail = no
joinempty = yes
leavewhenempty = no
maxlen = 300
memberdelay = 0
music = hamta
penaltymemberslimit = 0
periodic-announce-frequency = 240
queue-callswaiting = queue-callswaiting
queue-thankyou = queue-thankyou
queue-thereare = queue-thereare
queue-youarenext = queue-youarenext
periodic-announce = queue-periodic-announce
reportholdtime = no
retry = 2
ringinuse = no
servicelevel = 60
strategy = rrmemory
timeout = 14
timeoutpriority = app
timeoutrestart = yes
weight = 2
wrapuptime = 1
setinterfacevar = yes
setqueuevar = yes
context = queue-ivr

agents added dynamically by add queue member : Local/101@queue-agent

i monitor this auto destruct on zabbix and while i have this errors in server, i make a call and after hear ivr press 0, first hear nothing about 10 sec, but immidietlly after disapear auto destruct error from zabbix , my call can hear queue music on hold.
i check logs of this call and i can see below error when i press 0 and wait for 10 sec :

[Jul 14 12:24:29] WARNING[8067][C-000361c9] channel.c: Exceptionally long voice queue length queuing to Local/8082@from-internal-0007f2e9;2
[Jul 14 12:24:29] WARNING[8067][C-000361c9] channel.c: Exceptionally long voice queue length queuing to Local/8082@from-internal-0007f2e9;2

this auto destruct is making problem.

please please guide me friends.

You haven’t included the autodestruct message in your logs, so I can’t even tell if it indicates a problem, or is the normal one.

Your dialplan doesn’t include the channel that has the overlong queue.

i cant understand what you mean by : Your dialplan doesn’t include the channel that has the overlong queue ?!
i sent auto destruct log:

[root@astrsk_hamta ~]# grep 0004e5ff /var/log/asterisk/full
[Jul 14 13:42:42] VERBOSE[7177][C-00036e0c] pbx.c: Executing [096366@public:1] AGI("SIP/10.1.10.86-0004e5ff", "inbound-logger.php,096366") in new stack
[Jul 14 13:42:43] VERBOSE[7177][C-00036e0c] res_agi.c: inbound-logger.php,096366: CHANNEL: SIP/10.1.10.86-0004e5ff
[Jul 14 13:42:43] VERBOSE[7177][C-00036e0c] res_agi.c: inbound-logger.php,096366: AGI channel==>SIP/10.1.10.86-0004e5ff
[Jul 14 13:42:43] VERBOSE[7183][C-00036e0c] app_mixmonitor.c: Begin MixMonitor Recording SIP/10.1.10.86-0004e5ff
[Jul 14 13:42:45] VERBOSE[7177][C-00036e0c] file.c: <SIP/10.1.10.86-0004e5ff> Playing '/mnt/iwinstorage/iwin-Files/Hamta/2019/06/16/IVR_VOICES_5311613270127557442.slin' (language 'en')
[Jul 14 13:43:03] DTMF[7177][C-00036e0c] channel.c: DTMF begin '0' received on SIP/10.1.10.86-0004e5ff
[Jul 14 13:43:03] DTMF[7177][C-00036e0c] channel.c: DTMF begin ignored '0' on SIP/10.1.10.86-0004e5ff
[Jul 14 13:43:03] DTMF[7177][C-00036e0c] channel.c: DTMF end '0' received on SIP/10.1.10.86-0004e5ff, duration 115 ms
[Jul 14 13:43:03] DTMF[7177][C-00036e0c] channel.c: DTMF end passthrough '0' on SIP/10.1.10.86-0004e5ff
[Jul 14 13:43:05] VERBOSE[7177][C-00036e0c] app_dial.c: Local/8082@from-internal-000818af;1 answered SIP/10.1.10.86-0004e5ff
[Jul 14 13:43:05] VERBOSE[7177][C-00036e0c] bridge_channel.c: Channel SIP/10.1.10.86-0004e5ff joined 'simple_bridge' basic-bridge <9fc1647f-2c16-4a93-93e1-3b962f493b40>
[Jul 14 13:43:17] VERBOSE[7543][C-00036e0c] bridge_channel.c: Channel SIP/10.1.10.86-0004e5ff left 'simple_bridge' basic-bridge <9fc1647f-2c16-4a93-93e1-3b962f493b40>
[Jul 14 13:43:17] VERBOSE[7543][C-00036e0c] bridge_channel.c: Channel SIP/10.1.10.86-0004e5ff swapped with Local/8082@from-internal-000818af;2 into 'simple_bridge' basic-bridge <32df8efb-ee4e-40b7-8b02-42515a4b6587>
[Jul 14 13:47:04] VERBOSE[7177][C-00036e0c] bridge_channel.c: Channel SIP/10.1.10.86-0004e5ff left 'simple_bridge' basic-bridge <32df8efb-ee4e-40b7-8b02-42515a4b6587>
[Jul 14 13:47:04] VERBOSE[7177][C-00036e0c] res_agi.c: <SIP/10.1.10.86-0004e5ff>AGI Script inbound-logger.php completed, returning 4
[Jul 14 13:47:04] VERBOSE[7177][C-00036e0c] pbx.c: Spawn extension (public, 096366, 1) exited non-zero on 'SIP/10.1.10.86-0004e5ff'
[Jul 14 13:47:04] VERBOSE[7177][C-00036e0c] pbx.c: Executing [h@public:1] Verbose("SIP/10.1.10.86-0004e5ff", "") in new stack
[Jul 14 13:47:04] VERBOSE[7177][C-00036e0c] pbx.c: Executing [h@public:2] Verbose("SIP/10.1.10.86-0004e5ff", "HANGUP") in new stack
[Jul 14 13:47:04] VERBOSE[7177][C-00036e0c] pbx.c: Executing [h@public:3] Set("SIP/10.1.10.86-0004e5ff", "CDR(userfield)=10437523") in new stack
[Jul 14 13:47:36] WARNING[27838] chan_sip.c: Autodestruct on dialog 'isbcvagjedgkuqkf6hlgfse6h6kgau6equjl@SoftX3000' with owner SIP/10.1.10.86-0004e5ff in place (Method: BYE). Rescheduling destruction for 10000 ms
[Jul 14 13:47:39] VERBOSE[7177][C-00036e0c] pbx.c: Executing [h@public:4] Verbose("SIP/10.1.10.86-0004e5ff", "hangup cause : 16 for callid: 10437523") in new stack
[Jul 14 13:47:39] VERBOSE[7177][C-00036e0c] pbx.c: Executing [h@public:5] GotoIf("SIP/10.1.10.86-0004e5ff", "1?ack") in new stack
[Jul 14 13:47:43] VERBOSE[7177][C-00036e0c] pbx.c: Executing [h@public:7] GotoIf("SIP/10.1.10.86-0004e5ff", "0?hang") in new stack
[Jul 14 13:47:46] VERBOSE[7177][C-00036e0c] pbx.c: Executing [h@public:8] AGI("SIP/10.1.10.86-0004e5ff", "ack-logger.php,0,10437514,10437523,1563095562.2756640,5728445729098546782,,queue,7006") in new stack
[Jul 14 13:47:47] VERBOSE[7177][C-00036e0c] res_agi.c: <SIP/10.1.10.86-0004e5ff>AGI Script ack-logger.php completed, returning 0
[Jul 14 13:47:48] VERBOSE[7177][C-00036e0c] pbx.c: Executing [h@public:9] Hangup("SIP/10.1.10.86-0004e5ff", "") in new stack
[Jul 14 13:47:48] VERBOSE[7177][C-00036e0c] pbx.c: Spawn extension (public, h, 9) exited non-zero on 'SIP/10.1.10.86-0004e5ff'
[Jul 14 13:47:48] VERBOSE[7183][C-00036e0c] app_mixmonitor.c: End MixMonitor Recording SIP/10.1.10.86-0004e5ff

acctually after set cdr(userfield) , i can see about 32 sec delay and then auto destruct message.
are these related to each other.

please check this one
this is not exactly after cdr(userfield) but it happened after 32 sec.
cdr(userfield) is taking 31 sec and after 1 sec later “auto destruct” happened:

grep 0004c1c2 /var/log/asterisk/full
[Jul 14 10:40:20] VERBOSE[12097][C-000352fb] pbx.c: Executing [096366@public:1] AGI("SIP/10.1.10.86-0004c1c2", "inbound-logger.php,096366") in new stack
[Jul 14 10:40:20] VERBOSE[12097][C-000352fb] res_agi.c: inbound-logger.php,096366: CHANNEL: SIP/10.1.10.86-0004c1c2
[Jul 14 10:40:20] VERBOSE[12097][C-000352fb] res_agi.c: inbound-logger.php,096366: AGI channel==>SIP/10.1.10.86-0004c1c2
[Jul 14 10:40:20] VERBOSE[12127][C-000352fb] app_mixmonitor.c: Begin MixMonitor Recording SIP/10.1.10.86-0004c1c2
[Jul 14 10:40:23] VERBOSE[12097][C-000352fb] file.c: <SIP/10.1.10.86-0004c1c2> Playing '/mnt/iwinstorage/iwin-Files/Hamta/2019/06/16/IVR_VOICES_5311613270127557442.slin' (language 'en')
[Jul 14 10:41:13] DTMF[12097][C-000352fb] channel.c: DTMF begin '0' received on SIP/10.1.10.86-0004c1c2
[Jul 14 10:41:13] DTMF[12097][C-000352fb] channel.c: DTMF begin ignored '0' on SIP/10.1.10.86-0004c1c2
[Jul 14 10:41:13] DTMF[12097][C-000352fb] channel.c: DTMF end '0' received on SIP/10.1.10.86-0004c1c2, duration 95 ms
[Jul 14 10:41:13] DTMF[12097][C-000352fb] channel.c: DTMF end passthrough '0' on SIP/10.1.10.86-0004c1c2
[Jul 14 10:41:31] VERBOSE[12097][C-000352fb] app_dial.c: Local/8082@from-internal-0007c49f;1 answered SIP/10.1.10.86-0004c1c2
[Jul 14 10:41:32] VERBOSE[12097][C-000352fb] bridge_channel.c: Channel SIP/10.1.10.86-0004c1c2 joined 'simple_bridge' basic-bridge <ff5fcffb-af11-49d9-9f3e-40fb7652b49e>
[Jul 14 10:42:23] VERBOSE[13169][C-000352fb] bridge_channel.c: Channel SIP/10.1.10.86-0004c1c2 left 'simple_bridge' basic-bridge <ff5fcffb-af11-49d9-9f3e-40fb7652b49e>
[Jul 14 10:42:23] VERBOSE[13169][C-000352fb] bridge_channel.c: Channel SIP/10.1.10.86-0004c1c2 swapped with Local/8082@from-internal-0007c49f;2 into 'simple_bridge' basic-bridge <b1324379-ba18-476c-a6a0-2ca4ff6c4ae1>
[Jul 14 10:43:16] VERBOSE[12097][C-000352fb] bridge_channel.c: Channel SIP/10.1.10.86-0004c1c2 left 'simple_bridge' basic-bridge <b1324379-ba18-476c-a6a0-2ca4ff6c4ae1>
[Jul 14 10:43:18] VERBOSE[12097][C-000352fb] file.c: <SIP/10.1.10.86-0004c1c2> Playing '/mnt/iwinstorage/iwin-Files/Hamta/2019/06/16/IVR_VOICES_5600591377254493345.slin' (language 'en')
[Jul 14 10:43:19] VERBOSE[12097][C-000352fb] res_agi.c: <SIP/10.1.10.86-0004c1c2>AGI Script hangup.php completed, returning 4
[Jul 14 10:43:19] VERBOSE[12097][C-000352fb] res_agi.c: <SIP/10.1.10.86-0004c1c2>AGI Script inbound-logger.php completed, returning 4
[Jul 14 10:43:19] VERBOSE[12097][C-000352fb] pbx.c: Spawn extension (public, 096366, 1) exited non-zero on 'SIP/10.1.10.86-0004c1c2'
[Jul 14 10:43:19] VERBOSE[12097][C-000352fb] pbx.c: Executing [h@public:1] Verbose("SIP/10.1.10.86-0004c1c2", "") in new stack
[Jul 14 10:43:19] VERBOSE[12097][C-000352fb] pbx.c: Executing [h@public:2] Verbose("SIP/10.1.10.86-0004c1c2", "HANGUP") in new stack
[Jul 14 10:43:19] VERBOSE[12097][C-000352fb] pbx.c: Executing [h@public:3] Set("SIP/10.1.10.86-0004c1c2", "CDR(userfield)=10430643") in new stack
[Jul 14 10:43:50] VERBOSE[12097][C-000352fb] pbx.c: Executing [h@public:4] Verbose("SIP/10.1.10.86-0004c1c2", "hangup cause : 16 for callid: 10430643") in new stack
[Jul 14 10:43:50] VERBOSE[12097][C-000352fb] pbx.c: Executing [h@public:5] GotoIf("SIP/10.1.10.86-0004c1c2", "1?ack") in new stack
[Jul 14 10:43:50] VERBOSE[12097][C-000352fb] pbx.c: Executing [h@public:7] GotoIf("SIP/10.1.10.86-0004c1c2", "0?hang") in new stack
[Jul 14 10:43:50] VERBOSE[12097][C-000352fb] pbx.c: Executing [h@public:8] AGI("SIP/10.1.10.86-0004c1c2", "ack-logger.php,-2,10430634,10430643,1563084620.2653420,5632305448975047860,,poll,7019") in new stack
**[Jul 14 10:43:51] WARNING[27838] chan_sip.c: Autodestruct on dialog 'isbclllaejau6uugjaqfigsjvlheiievigjj@SoftX3000' with owner SIP/10.1.10.86-0004c1c2 in place (Method: BYE). Rescheduling destruction for 10000 ms**
[Jul 14 10:43:51] VERBOSE[12097][C-000352fb] res_agi.c: <SIP/10.1.10.86-0004c1c2>AGI Script ack-logger.php completed, returning 0
[Jul 14 10:43:51] VERBOSE[12097][C-000352fb] pbx.c: Executing [h@public:9] Hangup("SIP/10.1.10.86-0004c1c2", "") in new stack
[Jul 14 10:43:52] VERBOSE[12097][C-000352fb] pbx.c: Spawn extension (public, h, 9) exited non-zero on 'SIP/10.1.10.86-0004c1c2'
[Jul 14 10:43:52] VERBOSE[12127][C-000352fb] app_mixmonitor.c: End MixMonitor Recording SIP/10.1.10.86-0004c1c2

The following line appears to be taking an excessive amount of time to execute, which is why the auto-destruct is being delayed. Are you using a database, as that is the only reason I can see for it blocking for 25 seconds.

It is also possible that the delay is in evaluating the command line arguments for

but you haven’t provided the dialplan for the h extension, so I can’t tell if you are doing anything that is potentially slow.

Either way, the autodestruct message is a secondary symptom. The overrun of the h extension is causing that.

this is my h exten :

exten => h,1,verbose($[${ack${app}${i}${requestid}}])
exten => h,n,verbose(${AGISTATUS})
exten => h,n,set(CDR(userfield)=${callid})
exten => h,n,Verbose(hangup cause : ${HANGUPCAUSE} for callid: ${callid})
exten => h,n,gotoif($[${AGISTATUS} != SUCCESS]?ack)
exten => h,n,hangup()
exten => h,n(ack),gotoif($["$[${ack${app}${i}${requestid}}]"="done"]?hang)
exten => h,n(ack),agi(ack-logger.php,${ivrkey},${calllogid},${callid},${uniqi},${actionid},${meta},${app},${actiontype})
exten => h,n(hang),hangup()

i use odbc for cdr and save cdr on mssql with odbc driver.
how does cdr creates?
is it writing on database step by step or AT end of a call and just for one time
i see all cdr events raised at the end of a call.
i think that set(cdr(userfield)) is keeping on memory and save at the end. am i wrong???

Please markup your dialplan as preformatted text.

It’s definitely the set CDR that is blocking. I’m no sure of the internals of CDR handlign and it has been reworked since I looked at the code in any detail.

There could be locks held by CDR processing that is writing to the database. One would need to compile with thread debugging, and use core show locks, or at least take a snapshot core dump and look for threads blocked on locks, etc., to see in detail whether there was a lock held by another thread.

i don’t have this command in my console. no such command “core show locks”
can you quid me to “compile with thread debugging, and use core show locks” and how to taking a snapshot core dump
thanks million

https://wiki.asterisk.org/wiki/display/AST/Getting+a+Backtrace

https://wiki.asterisk.org/wiki/display/AST/CLI+commands+useful+for+debugging

https://wiki.asterisk.org/wiki/display/AST/Installing+Asterisk+From+Source

i found that error “Exceptionally long voice queue length queuing” is for set another CDR param again :

[Jul 15 13:06:31] VERBOSE[26514][C-0003c3d8] pbx.c: Executing [s@macro-mixmon:7] Set("Local/8083@from-internal-00091223;2", "CDR(recordingfile)=1563179786.3069238") in new stack
[Jul 15 13:06:33] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:34] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:35] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:37] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:38] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:39] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:40] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:42] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:43] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:44] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:45] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:47] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:48] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:49] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:51] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:52] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:53] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:54] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2
[Jul 15 13:06:56] WARNING[26414][C-0003c3d8] channel.c: Exceptionally long voice queue length queuing to Local/8083@from-internal-00091223;2

i need this parameter to be passed to cdr , what do you suggest me to do for solving this issue.
problem exist just when calls reach to 70 or more

now i’m sure that writing to cdr is making delay and above error and finally slowness in system and …
please help me.

i use odbc for cdr , do you thinks is there any problem with odbc?!
i use it for Mssql server and mysql too.

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