[Asterisk-Users] queue_log wrong?

[Adam Goryachev]

Well, I'm writing yet another queue_log analyser program in PHP, and I
have noticed the following entry in my queue_log file from today:
1104796626|1104796618.532|queue|NONE|ENTERQUEUE||no
1104796664|1104796618.532|queue|NONE|EXITWITHTIMEOUT|1

So, pretty sure that I didn't make someone wait 30 minutes in my queue.
extensions.conf snippet:
[remote-oldnum]
exten => s,1,Answer
exten => s,2,Goto(remote,s,1)

[remote]
exten => s,1,Monitor(,${UNIQUEID},m)
exten => s,2,DigitTimeout,5
exten => s,3,ResponseTimeout,10
exten => s,4,SetMusicOnHold,default
exten => s,5,Answer
exten => s,6,Background(local/Thanks_for_calling)
exten => s,7,Background(this-call-may-be)
exten => s,8,SetVar(QUEUE_PRIO=1)
exten => s,9,SetVar(QUEUE_PRIO=$[${QUEUE_PRIO} + 1])
exten => s,10,Queue(queue,tn,,,1800)

so I looked at various things.

First, I looked at the recorded file (monitor in step 1) and realised I
did indeed answer the call, almost immediately, and spoke at length with
a customer.

So, I looked in various other asterisk log files until I got to the
debug.log file and found the below output.

Note, this is a analog FXO interface, hence the immediate answer.

Also, I'd be interested to know why there are so many format changes,
and how I might force the format to alaw...

So, in short, the queue_log logfile is wrong, but I can't find any
information as to why....

Regards,
Adam

2005-01-04 11:28:43 DEBUG[5537]: Monitor doohicky got event
Ring/Answered on channel 125
2005-01-04 11:28:43 DEBUG[5967]: Launching 'Answer'
2005-01-04 11:28:43 DEBUG[5967]: Took Zap/125-1 off hook
2005-01-04 11:28:43 DEBUG[5967]: No echocancellation requested
2005-01-04 11:28:43 DEBUG[5967]: No echo training requested
2005-01-04 11:28:43 DEBUG[5967]: Launching 'Goto'
2005-01-04 11:28:43 DEBUG[5967]: Launching 'Monitor'
2005-01-04 11:28:43 DEBUG[5967]: Launching 'DigitTimeout'
2005-01-04 11:28:43 DEBUG[5967]: Launching 'ResponseTimeout'
2005-01-04 11:28:43 DEBUG[5967]: Launching 'SetMusicOnHold'
2005-01-04 11:28:43 DEBUG[5967]: Launching 'Answer'
2005-01-04 11:28:43 DEBUG[5967]: Launching 'BackGround'
2005-01-04 11:28:43 DEBUG[5967]: Set channel Zap/125-1 to write format
gsm
2005-01-04 11:28:43 DEBUG[5967]: Scheduling timer at 160 sample
intervals
2005-01-04 11:28:48 DEBUG[5534]: Allocating new SIP call for (null)
2005-01-04 11:28:48 DEBUG[5534]: Stopping retransmission on
'6ac3e55b550fde917002fbc02608e64c at 192.168.2.122' of Request 102: Found
2005-01-04 11:28:48 DEBUG[5967]: Scheduling timer at 0 sample intervals
2005-01-04 11:28:48 DEBUG[5967]: Scheduling timer at 0 sample intervals
2005-01-04 11:28:48 DEBUG[5967]: Set channel Zap/125-1 to write format
ulaw
2005-01-04 11:28:48 DEBUG[5967]: Launching 'BackGround'
2005-01-04 11:28:48 DEBUG[5967]: Set channel Zap/125-1 to write format
gsm
2005-01-04 11:28:48 DEBUG[5967]: Scheduling timer at 160 sample
intervals
2005-01-04 11:28:52 DEBUG[5967]: Scheduling timer at 0 sample intervals
2005-01-04 11:28:52 DEBUG[5967]: Scheduling timer at 0 sample intervals
2005-01-04 11:28:52 DEBUG[5967]: Set channel Zap/125-1 to write format
ulaw
2005-01-04 11:28:52 DEBUG[5967]: Launching 'SetVar'
2005-01-04 11:28:52 DEBUG[5967]: Expression is '2'
2005-01-04 11:28:52 DEBUG[5967]: Launching 'SetVar'
2005-01-04 11:28:52 DEBUG[5967]: Launching 'Queue'
2005-01-04 11:28:52 DEBUG[5967]: Zap/125-1: Got priority 2 from
${QUEUE_PRIO}.
2005-01-04 11:28:52 DEBUG[5967]: queue: queue, options: tn, url: ,
announce: , timeout: 1800, priority: 2
2005-01-04 11:28:52 DEBUG[5967]: Set channel Zap/125-1 to write format
slin
2005-01-04 11:28:52 DEBUG[5967]: Scheduling timer at 160 sample
intervals
2005-01-04 11:28:52 DEBUG[5967]: It's our turn (Zap/125-1).
2005-01-04 11:28:52 DEBUG[5967]: Zap/125-1 is trying to call a queue
member.
2005-01-04 11:28:52 DEBUG[5967]: Queue with URL=_
2005-01-04 11:28:52 DEBUG[5967]: (Parallel) Trying 'SIP/polycom_a1' with
metric 0
2005-01-04 11:28:52 DEBUG[5967]: Allocating new SIP call for (null)
2005-01-04 11:28:52 DEBUG[5967]: Setting NAT on RTP to 0
2005-01-04 11:28:52 DEBUG[5967]: Outgoing Call for polycom_a1
2005-01-04 11:28:52 DEBUG[5967]: Call from user 'polycom_a1' is 1 out of
0
2005-01-04 11:28:52 DEBUG[5967]: Generator got voice, switching to phase
locked mode
2005-01-04 11:28:52 DEBUG[5967]: Scheduling timer at 0 sample intervals
2005-01-04 11:28:52 DEBUG[5534]: (Provisional) Stopping retransmission
(but retaining packet) on
'31f7d00c69dbf5d367c910504c2241ec at 192.168.2.122' Request 102: Found
2005-01-04 11:28:52 DEBUG[5534]: (Provisional) Stopping retransmission
(but retaining packet) on
'31f7d00c69dbf5d367c910504c2241ec at 192.168.2.122' Request 102: Found
2005-01-04 11:28:59 DEBUG[5534]: Acked pending invite 102
2005-01-04 11:28:59 DEBUG[5534]: Stopping retransmission on
'31f7d00c69dbf5d367c910504c2241ec at 192.168.2.122' of Request 102: Found
2005-01-04 11:28:59 DEBUG[5534]: build_route: Contact hop:
<sip:polycom_a1 at 192.168.2.3>
2005-01-04 11:28:59 DEBUG[5967]: Set option TONE VERIFY, mode:
MUTECONF/MAX(2) on Zap/125-1
2005-01-04 11:28:59 DEBUG[5967]: Set channel Zap/125-1 to write format
ulaw
2005-01-04 11:28:59 DEBUG[5967]: Scheduling timer at 0 sample intervals
2005-01-04 11:28:59 DEBUG[5967]: Set channel Zap/125-1 to read format
alaw
2005-01-04 11:28:59 DEBUG[5967]: Set channel SIP/polycom_a1-aec3 to
write format alaw
2005-01-04 11:28:59 DEBUG[5967]: Set channel Zap/125-1 to write format
ulaw
2005-01-04 11:28:59 DEBUG[5967]: Set channel SIP/polycom_a1-aec3 to read
format ulaw
2005-01-04 11:28:59 DEBUG[5967]: Ooh, format changed from unknown to
alaw
2005-01-04 11:29:02 DEBUG[5967]: Got RTCP report of 100 bytes
2005-01-04 11:29:12 DEBUG[5967]: Got RTCP report of 100 bytes
2005-01-04 11:29:22 DEBUG[5967]: Got RTCP report of 100 bytes
2005-01-04 11:29:29 DEBUG[5534]: Allocating new SIP call for
ca242c18b15c8c30 at 192.168.2.26
2005-01-04 11:29:32 DEBUG[5967]: Got RTCP report of 100 bytes
2005-01-04 11:29:36 DEBUG[5534]: Allocating new SIP call for (null)
2005-01-04 11:29:36 DEBUG[5534]: Allocating new SIP call for (null)
2005-01-04 11:29:36 DEBUG[5534]: Stopping retransmission on
'3321e4f7172b768e108b14a11a4d616c at 192.168.2.122' of Request 102: Found
2005-01-04 11:29:36 DEBUG[5534]: Stopping retransmission on
'08b60af567032d240e53b4a0121969d0 at 192.168.2.122' of Request 102: Found
2005-01-04 11:29:39 DEBUG[5534]: Allocating new SIP call for (null)
2005-01-04 11:29:39 DEBUG[5534]: Setting NAT on RTP to 0
2005-01-04 11:29:39 DEBUG[5534]: Stopping retransmission on
'40453e5b124c83ed0e5ae95673672353 at websitemanagers.com.au' of Request
102: Found
2005-01-04 11:29:42 DEBUG[5967]: Got RTCP report of 100 bytes
2005-01-04 11:29:47 DEBUG[5534]: Auto destroying call
'ca242c18b15c8c30 at 192.168.2.26'
2005-01-04 11:29:48 DEBUG[5534]: Allocating new SIP call for (null)
2005-01-04 11:29:48 DEBUG[5534]: Stopping retransmission on
'5960d2c23e98aae6458da1c41a352741 at 192.168.2.122' of Request 102: Found
2005-01-04 11:29:52 DEBUG[5967]: Got RTCP report of 100 bytes
2005-01-04 11:30:02 DEBUG[5967]: Got RTCP report of 100 bytes
2005-01-04 11:30:12 DEBUG[5967]: Got RTCP report of 100 bytes
2005-01-04 11:30:17 DEBUG[5967]: Didn't get a frame from channel:
SIP/polycom_a1-aec3
2005-01-04 11:30:17 DEBUG[5967]: Bridge stops bridging channels
Zap/125-1 and SIP/polycom_a1-aec3
2005-01-04 11:30:17 DEBUG[5967]: Hanging up channel
'SIP/polycom_a1-aec3'
2005-01-04 11:30:17 DEBUG[5967]: sip_hangup(SIP/polycom_a1-aec3)
2005-01-04 11:30:17 DEBUG[5967]: update_user_counter(polycom_a1) -
decrement outUse counter
2005-01-04 11:30:17 DEBUG[5967]: Spawn extension (remote,s,10) exited
non-zero on 'Zap/125-1'
2005-01-04 11:30:17 DEBUG[5967]: Hanging up channel 'Zap/125-1'
2005-01-04 11:30:17 DEBUG[5967]: zt_hangup(Zap/125-1)
2005-01-04 11:30:17 DEBUG[5967]: Hangup: channel: 125 index = 0, normal
= 41, callwait = -1, thirdcall = -1
2005-01-04 11:30:17 DEBUG[5967]: Set option TDD MODE, value: OFF(0) on
Zap/125-1
2005-01-04 11:30:17 DEBUG[5967]: Updated conferencing on 125, with 0
conference users

-- 
 -- 
Adam Goryachev
Website Managers
Ph:  +61 2 8304 0000                        adam at websitemanagers.com.au
Fax: +61 2 9345 4396                        www.websitemanagers.com.au