Call disconnected in a queue with Agi script

Hello @all
I’m using asterisk 1.8.16.0 and I configure an inbound queue with an AGI script.
Customer compliants calls disconnected after 2/3 seconds of hold in the queue.
I collect the debug log from Asterisk of one fault. Please can you analyze the log and tell me if you see some error or something that can explain the disconnection?

Thank you in advance,
Luca

[Jul  1 14:29:22] DEBUG[16367] pbx.c: Launching 'Set'
[Jul  1 14:29:22] VERBOSE[16367] pbx.c:     -- Executing [388@default:1] Set("SIP/192.168.101.198-00009b44", "CHANNEL(language)=it") in new stack
[Jul  1 14:29:22] DEBUG[16367] pbx.c: Launching 'Set'
[Jul  1 14:29:22] VERBOSE[16367] pbx.c:     -- Executing [388@default:2] Set("SIP/192.168.101.198-00009b44", "CALLERID(name)=SGR") in new stack
[Jul  1 14:29:22] DEBUG[16367] pbx.c: Function result is '"SGR" <0543560943>'
[Jul  1 14:29:22] DEBUG[16367] pbx.c: Launching 'NoOp'
[Jul  1 14:29:22] VERBOSE[16367] pbx.c:     -- Executing [388@default:3] NoOp("SIP/192.168.101.198-00009b44", ""CHIAMANTE: "SGR" <0543560943>"") in new stack
[Jul  1 14:29:22] DEBUG[16367] pbx.c: Result of 'AGIDIR' is '/var/www/html/asterisk/agi-bin'
[Jul  1 14:29:22] DEBUG[16367] pbx.c: Result of 'UNIQUEID' is '1404217762.40936'
[Jul  1 14:29:22] DEBUG[16367] pbx.c: Function result is '0543560943'
[Jul  1 14:29:22] DEBUG[16367] pbx.c: Launching 'AGI'
[Jul  1 14:29:22] VERBOSE[16367] pbx.c:     -- Executing [388@default:4] AGI("SIP/192.168.101.198-00009b44", "/var/www/html/asterisk/agi-bin/call_center/script/cc-500.php,1404217762.40936,0543560943") in new stack
[Jul  1 14:29:22] VERBOSE[16367] res_agi.c:     -- Launched AGI Script /var/www/html/asterisk/agi-bin/call_center/script/cc-500.php
[Jul  1 14:29:22] DEBUG[16367] chan_sip.c: SIP answering channel: SIP/192.168.101.198-00009b44
[Jul  1 14:29:22] DEBUG[16367] res_rtp_asterisk.c: Setting the marker bit due to a source update
[Jul  1 14:29:22] DEBUG[16367] chan_sip.c: Setting framing from config on incoming call
[Jul  1 14:29:22] DEBUG[16367] chan_sip.c: ** Our capability: 0x8 (alaw) Video flag: True Text flag: True
[Jul  1 14:29:22] DEBUG[16367] chan_sip.c: ** Our prefcodec: 0x0 (nothing) 
[Jul  1 14:29:22] DEBUG[16367] chan_sip.c: -- Done with adding codecs to SDP
[Jul  1 14:29:22] DEBUG[16367] chan_sip.c: Done building SDP. Settling with this capability: 0x8 (alaw)
[Jul  1 14:29:22] DEBUG[16367] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.101.190:5060
[Jul  1 14:29:22] VERBOSE[16367] res_agi.c:     -- AGI Script Executing Application: (PLAYBACK) Options: (/var/www/html/asterisk/agi-bin/call_center/messaggi/BenvenutoInSGRServizi)
[Jul  1 14:29:22] DEBUG[16367] channel.c: Set channel SIP/192.168.101.198-00009b44 to write format slin
[Jul  1 14:29:22] DEBUG[16367] res_rtp_asterisk.c: Ooh, format changed from unknown to alaw
[Jul  1 14:29:22] DEBUG[16367] res_rtp_asterisk.c: Created smoother: format: alaw ms: 20 len: 160
[Jul  1 14:29:22] DEBUG[16367] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jul  1 14:29:22] VERBOSE[16367] file.c:     -- <SIP/192.168.101.198-00009b44> Playing '/var/www/html/asterisk/agi-bin/call_center/messaggi/BenvenutoInSGRServizi.slin' (language 'it')
[Jul  1 14:29:26] DEBUG[16367] channel.c: Scheduling timer at (421 requested / 100 actual) timer ticks per second
[Jul  1 14:29:26] DEBUG[16367] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 14:29:26] DEBUG[16367] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 14:29:26] DEBUG[16367] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 14:29:26] DEBUG[16367] channel.c: Set channel SIP/192.168.101.198-00009b44 to write format alaw
[Jul  1 14:29:26] VERBOSE[16367] res_agi.c:     -- AGI Script Executing Application: (PLAYBACK) Options: (/var/www/html/asterisk/agi-bin/call_center/messaggi/scelta_lettura_operatore_aperto)
[Jul  1 14:29:26] DEBUG[16367] channel.c: Set channel SIP/192.168.101.198-00009b44 to write format slin
[Jul  1 14:29:26] DEBUG[16367] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jul  1 14:29:26] VERBOSE[16367] file.c:     -- <SIP/192.168.101.198-00009b44> Playing '/var/www/html/asterisk/agi-bin/call_center/messaggi/scelta_lettura_operatore_aperto.slin' (language 'it')
[Jul  1 14:29:27] DEBUG[16367] res_rtp_asterisk.c: Got RTCP report of 80 bytes
[Jul  1 14:29:32] DEBUG[16367] res_rtp_asterisk.c: Got RTCP report of 80 bytes
[Jul  1 14:29:37] DEBUG[16367] res_rtp_asterisk.c: Got RTCP report of 80 bytes
[Jul  1 14:29:38] DEBUG[16367] channel.c: Scheduling timer at (53 requested / 53 actual) timer ticks per second
[Jul  1 14:29:38] DEBUG[16367] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 14:29:38] DEBUG[16367] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 14:29:38] DEBUG[16367] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 14:29:38] DEBUG[16367] channel.c: Set channel SIP/192.168.101.198-00009b44 to write format alaw
[Jul  1 14:29:38] DEBUG[16367] channel.c: Set channel SIP/192.168.101.198-00009b44 to write format ulaw
[Jul  1 14:29:38] DEBUG[16367] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jul  1 14:29:38] VERBOSE[16367] file.c:     -- <SIP/192.168.101.198-00009b44> Playing 'beep.ulaw' (language 'it')
[Jul  1 14:29:38] DEBUG[16367] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 14:29:38] DEBUG[16367] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 14:29:38] DEBUG[16367] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 14:29:38] DEBUG[16367] channel.c: Set channel SIP/192.168.101.198-00009b44 to write format alaw
[Jul  1 14:29:42] DEBUG[16367] res_rtp_asterisk.c: Got RTCP report of 80 bytes
[Jul  1 14:29:43] VERBOSE[16367] res_agi.c:     -- AGI Script Executing Application: (QUEUE) Options: (500)
[Jul  1 14:29:43] DEBUG[16367] app_queue.c: NO QUEUE_PRIO variable found. Using default.
[Jul  1 14:29:43] DEBUG[16367] app_queue.c: queue: 500, options: (null), url: (null), announce: (null), expires: 0, priority: 0
[Jul  1 14:29:43] DEBUG[16367] app_queue.c: Queue 500 has no realtime members defined. No need for update
[Jul  1 14:29:43] DEBUG[16367] app_queue.c: Queue '500' Join, Channel 'SIP/192.168.101.198-00009b44', Position '1'
[Jul  1 14:29:43] VERBOSE[16367] res_musiconhold.c:     -- Started music on hold, class 'default', on SIP/192.168.101.198-00009b44
[Jul  1 14:29:43] DEBUG[16367] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second
[Jul  1 14:29:43] DEBUG[16367] app_queue.c: There are 3 available members.
[Jul  1 14:29:43] DEBUG[16367] app_queue.c: It's our turn (SIP/192.168.101.198-00009b44).
[Jul  1 14:29:43] DEBUG[16367] app_queue.c: SIP/192.168.101.198-00009b44 is trying to call a queue member.
[Jul  1 14:29:43] DEBUG[16367] app_queue.c: Trying 'sip/103' with metric 5000004
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: Asked to create a SIP channel with formats: 0x8 (alaw)
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: Allocating new SIP dialog for 173b2e1c637b21311c409e067b6f5213@192.168.101.198:5060 - INVITE (No RTP)
[Jul  1 14:29:43] DEBUG[16367] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x8de5080'
[Jul  1 14:29:43] DEBUG[16367] res_rtp_asterisk.c: Allocated port 19210 for RTP instance '0x8de5080'
[Jul  1 14:29:43] DEBUG[16367] rtp_engine.c: RTP instance '0x8de5080' is setup and ready to go
[Jul  1 14:29:43] DEBUG[16367] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x8de5080'
[Jul  1 14:29:43] VERBOSE[16367] netsock2.c:   == Using SIP RTP CoS mark 5
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: Setting NAT on RTP to Off
[Jul  1 14:29:43] DEBUG[16367] acl.c: For destination '192.168.101.103', our source address is '192.168.101.198'.
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.101.198:5060
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: *** Our native formats are 0x8 (alaw) 
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: *** Joint capabilities are 0x8 (alaw) 
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: *** Our capabilities are 0xc (ulaw|alaw) 
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) 
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: *** Our preferred formats from the incoming channel are 0x8 (alaw) 
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: This channel will not be able to handle video.
[Jul  1 14:29:43] DEBUG[16367] channel.c: Not copying variable PLAYBACKSTATUS.
[Jul  1 14:29:43] DEBUG[16367] channel.c: Not copying variable SIPCALLID.
[Jul  1 14:29:43] DEBUG[16367] channel.c: Not copying variable SIPDOMAIN.
[Jul  1 14:29:43] DEBUG[16367] channel.c: Not copying variable SIPURI.
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: Outgoing Call for 103
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: Updating call counter for outgoing call
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: ** Our capability: 0xc (ulaw|alaw) Video flag: False Text flag: False
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: ** Our prefcodec: 0x8 (alaw) 
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: -- Done with adding codecs to SDP
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: Done building SDP. Settling with this capability: 0xc (ulaw|alaw)
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: Initializing initreq for method INVITE - callid 51af2ab7481218c56a61ae47041a070b@192.168.101.198:5060
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for 192.168.101.103:5060
[Jul  1 14:29:43] DEBUG[16367] devicestate.c: No provider found, checking channel drivers for sip - 103
[Jul  1 14:29:43] DEBUG[16367] chan_sip.c: Checking device state for peer 103
[Jul  1 14:29:43] DEBUG[16367] channel.c: Generator got voice, switching to phase locked mode
[Jul  1 14:29:43] DEBUG[16367] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 14:29:43] DEBUG[16367] channel.c: Set channel SIP/192.168.101.198-00009b44 to write format slin
[Jul  1 14:29:43] DEBUG[16367] res_musiconhold.c: SIP/192.168.101.198-00009b44 Opened file 0 '/var/lib/asterisk/moh/macroform-cold_day'
[Jul  1 14:29:43] DEBUG[16367] res_rtp_asterisk.c: Difference is 41624, ms is 5223
[Jul  1 14:29:44] VERBOSE[16367] app_queue.c:     -- SIP/103-00009b45 is ringing
[Jul  1 14:29:45] VERBOSE[16367] res_musiconhold.c:     -- Stopped music on hold on SIP/192.168.101.198-00009b44
[Jul  1 14:29:45] DEBUG[16367] channel.c: Set channel SIP/192.168.101.198-00009b44 to write format alaw
[Jul  1 14:29:45] DEBUG[16367] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Jul  1 14:29:45] DEBUG[16367] app_queue.c: Next is 'sip/125' with metric 5000005
[Jul  1 14:29:45] DEBUG[16367] app_queue.c: SIP/192.168.101.198-00009b44: Nobody answered.
[Jul  1 14:29:45] DEBUG[16367] channel.c: Hanging up channel 'SIP/103-00009b45'
[Jul  1 14:29:45] DEBUG[16367] chan_sip.c: Hangup call SIP/103-00009b45, SIP callid 51af2ab7481218c56a61ae47041a070b@192.168.101.198:5060
[Jul  1 14:29:45] DEBUG[16367] chan_sip.c: Updating call counter for outgoing call
[Jul  1 14:29:45] DEBUG[16367] chan_sip.c: Hanging up channel in state Ringing (not UP)
[Jul  1 14:29:45] DEBUG[16367] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8de5080'
[Jul  1 14:29:45] DEBUG[16367] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '51af2ab7481218c56a61ae47041a070b@192.168.101.198:5060' Request 102: Found
[Jul  1 14:29:45] DEBUG[16367] chan_sip.c: Trying to put 'CANCEL sip:' onto UDP socket destined for 192.168.101.103:5060
[Jul  1 14:29:45] DEBUG[16367] cdr.c: Dropping CDR !
[Jul  1 14:29:45] DEBUG[16367] app_queue.c: Queue '500' Leave, Channel 'SIP/192.168.101.198-00009b44'
[Jul  1 14:29:45] DEBUG[16367] res_agi.c: SIP/192.168.101.198-00009b44 hungup
[Jul  1 14:29:45] VERBOSE[16367] res_agi.c:     -- <SIP/192.168.101.198-00009b44>AGI Script /var/www/html/asterisk/agi-bin/call_center/script/cc-500.php completed, returning 4
[Jul  1 14:29:45] DEBUG[16367] pbx.c: Spawn extension (default,388,4) exited non-zero on 'SIP/192.168.101.198-00009b44'
[Jul  1 14:29:45] VERBOSE[16367] pbx.c:   == Spawn extension (default, 388, 4) exited non-zero on 'SIP/192.168.101.198-00009b44'
[Jul  1 14:29:45] DEBUG[16367] channel.c: Soft-Hanging up channel 'SIP/192.168.101.198-00009b44'
[Jul  1 14:29:45] DEBUG[16367] channel.c: Hanging up channel 'SIP/192.168.101.198-00009b44'
[Jul  1 14:29:45] DEBUG[16367] chan_sip.c: Hangup call SIP/192.168.101.198-00009b44, SIP callid 4e8cf4643fa71f6b
[Jul  1 14:29:45] DEBUG[16367] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x8ed75a8'
[Jul  1 14:29:45] DEBUG[16367] cdr.c: Dropping CDR !

It’s trying to ring and agent, but behaving as though timeout was set to 1 second.

This is the queues.conf

[general]
persistentmembers = yes
autofill = yes
monitor-type = MixMonitor
shared_lastcall=yes

;coda SGR
[500]
musicclass = default
announce-frequency=25
announce-position = yes
periodic-announce-frequency=0
queue-callswaiting=/var/www/html/asterisk/agi-bin/call_center/messaggi/coda2-2
queue-thankyou=/var/www/html/asterisk/agi-bin/call_center/messaggi/msg_callback
queue-thereare=/var/www/html/asterisk/agi-bin/call_center/messaggi/coda1-2
queue-youarenext=/var/www/html/asterisk/agi-bin/call_center/messaggi/sei_il_primo
retry=1
;strategy=leastrecent
strategy=rrmemory
;strategy=linear
timeout=10
periodic-announce=
announce-holdtime=no
context=callback_800900147
eventmemberstatus=no
eventwhencalled=no
joinempty=yes
leavewhenempty=no
maxlen=0
monitor-format=
wrapuptime=40
weight=10
servicelevel=180
setinterfacevar=no
ringinuse = no

timeout is set to 10.

Why I have this strange behavior?