WipeOut
2004-Nov-20 10:39 UTC
[Asterisk-Users] Can anyone shed some light on wht these calls were dropped?
Hi, I need help finding why my system is dropping calls.. I enabled debugging on my box in the hope it would lead me to the answer as to why my system is dropping calls but unfortunately nothing is jumping out at me.. I have attached the portion of the messages file for two calls that were dropped.. (numbers names and ip's have been changes to protect the innocent) Can someone give me a reason why the calls were dropped? or maybe tell me where to look.... My only thought is that its a loosing some packets as it goes across the internet to the IAX provider and that the tolerance for packet loss is set really low so it drops the call completely.. Any help appreciated.. Thanks.. -------------- next part -------------- Nov 20 16:52:00 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 16:52:00 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:52:00 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:52:00 DEBUG[-1109894224]: DTMF digit: 1 on Zap/2-1 Nov 20 16:52:00 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 16:52:00 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:52:01 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 16:52:01 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:52:01 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 16:52:01 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:52:01 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 16:52:02 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:52:02 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 16:52:02 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:52:05 DEBUG[-1109894224]: Enabled echo cancellation on channel 2 Nov 20 16:52:05 DEBUG[-1109894224]: Made call 5 into trunk call 16384 Nov 20 16:52:05 DEBUG[-1109894224]: Created trunk peer for '111.222.333.444:4569' Nov 20 16:52:05 DEBUG[-1109894224]: Expanded trunk '111.222.333.444:4569' to 6400 bytes Nov 20 16:52:07 DEBUG[-1109894224]: Received AST_CONTROL_PROGRESS on Zap/2-1 Nov 20 16:52:07 DEBUG[-1095144528]: Ooh, voice format changed to 1024 Nov 20 16:52:15 DEBUG[-1109894224]: Took Zap/2-1 off hook Nov 20 16:53:35 DEBUG[-1090942032]: Setting NAT on RTP to 0 Nov 20 16:53:36 DEBUG[-1090942032]: Stopping retransmission on '689f34b07622328c08f11b0a14c10311@192.168.1.9' of Request 102: Found Nov 20 16:53:48 DEBUG[-1090942032]: Auto destroying call '87dc40df1ff65be9@192.168.1.23' Nov 20 16:55:01 DEBUG[-1109894224]: Exception on 17, channel 2 Nov 20 16:55:01 DEBUG[-1109894224]: Got event Wink/Flash(3) on channel 2 (index 0) Nov 20 16:55:01 DEBUG[-1109894224]: Winkflash, index: 0, normal: 17, callwait: -1, thirdcall: -1 Nov 20 16:55:01 DEBUG[-1109894224]: Already have a dsp on Zap/2-2? Nov 20 16:55:01 DEBUG[-1109894224]: Swapping 2 and 0 Nov 20 16:55:01 DEBUG[-1109894224]: disabled echo cancellation on channel 2 Nov 20 16:55:01 DEBUG[-1109894224]: Updated conferencing on 2, with 0 conference users Nov 20 16:55:04 DEBUG[-1111995472]: Exception on 17, channel 2 Nov 20 16:55:04 DEBUG[-1111995472]: Got event On hook(1) on channel 2 (index 0) Nov 20 16:55:04 DEBUG[-1111995472]: Last flash was 2764 ms ago Nov 20 16:55:04 DEBUG[-1111995472]: Swapping 2 and 0 Nov 20 16:55:05 DEBUG[-1111995472]: disabled echo cancellation on channel 2 Nov 20 16:55:05 DEBUG[-1111995472]: waitfordigit returned < 0... Nov 20 16:55:05 DEBUG[-1111995472]: Hangup: channel: 2 index = 2, normal = 17, callwait = -1, thirdcall = 21 Nov 20 16:55:05 DEBUG[-1111995472]: Released sub 2 of channel 2 Nov 20 16:55:06 WARNING[-1095144528]: Max retries exceeded to host 111.222.333.444 on IAX2/provider-out/16384 (type = 6, subclass = 2, ts=160005, seqno=47) Nov 20 16:55:06 WARNING[-1095144528]: Max retries exceeded to host 111.222.333.444 on IAX2/provider-out/16384 (type = 6, subclass = 11, ts=160008, seqno=48) Nov 20 16:55:06 DEBUG[-1109894224]: Didn't get a frame from channel: IAX2/provider-out/16384 Nov 20 16:55:06 DEBUG[-1109894224]: Bridge stops bridging channels Zap/2-1 and IAX2/provider-out/16384 Nov 20 16:55:06 DEBUG[-1109894224]: We're hanging up IAX2/provider-out/16384 now... Nov 20 16:55:06 DEBUG[-1109894224]: Exiting with DIALSTATUS=ANSWER. Nov 20 16:55:06 DEBUG[-1109894224]: cdr_mysql: inserting a CDR record. Nov 20 16:55:06 DEBUG[-1109894224]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2004-11-20 16:52:05','\"Cordless Phone\" <1234>','1234','90019090909090','local', 'Zap/2-1','IAX2/provider-out/16384','Dial','IAX2/user1@provider-out/19058289575',181,171,'ANSWERED',3,'Cordless Phone') Nov 20 16:55:06 DEBUG[-1109894224]: Hangup: channel: 2 index = 0, normal = 17, callwait = -1, thirdcall = -1 Nov 20 16:55:06 DEBUG[-1109894224]: disabled echo cancellation on channel 2 Nov 20 16:55:06 DEBUG[-1109894224]: Set option TDD MODE, value: OFF(0) on Zap/2-1 Nov 20 16:55:06 DEBUG[-1109894224]: Updated conferencing on 2, with 0 conference users Nov 20 16:55:08 DEBUG[-1095144528]: Immediately destroying 16384, having received hangup Nov 20 16:55:08 DEBUG[-1095144528]: Raw Hangup 111.222.333.444:4569, src=16384, dst=16385 Nov 20 16:55:08 DEBUG[-1095144528]: Raw Hangup 111.222.333.444:4569, src=16384, dst=16385 Nov 20 16:55:08 DEBUG[-1095144528]: Raw Hangup 111.222.333.444:4569, src=16384, dst=16385 Nov 20 16:55:12 DEBUG[-1095144528]: Dropping unused iax2 trunk peer '111.222.333.444:4569' Nov 20 16:55:19 DEBUG[-1109894224]: Exception on 17, channel 2 Nov 20 16:55:19 DEBUG[-1109894224]: Got event On hook(1) on channel 2 (index 0) Nov 20 16:55:19 DEBUG[-1109894224]: disabled echo cancellation on channel 2 Nov 20 16:55:19 DEBUG[-1109894224]: waitfordigit returned < 0... Nov 20 16:55:19 DEBUG[-1109894224]: Hangup: channel: 2 index = 0, normal = 17, callwait = -1, thirdcall = -1 Nov 20 16:55:19 DEBUG[-1109894224]: disabled echo cancellation on channel 2 Nov 20 16:55:19 DEBUG[-1109894224]: Set option TDD MODE, value: OFF(0) on Zap/2-1 Nov 20 16:55:19 DEBUG[-1109894224]: Updated conferencing on 2, with 0 conference users Nov 20 16:55:33 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 16:55:33 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:55:33 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:55:33 DEBUG[-1109894224]: DTMF digit: 1 on Zap/2-1 Nov 20 16:55:33 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 16:55:33 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:55:34 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 16:55:34 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:55:34 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 16:55:34 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:55:34 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 16:55:35 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:55:35 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 16:55:35 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 16:55:38 DEBUG[-1109894224]: Enabled echo cancellation on channel 2 Nov 20 16:55:38 DEBUG[-1109894224]: Made call 3 into trunk call 16385 Nov 20 16:55:38 DEBUG[-1109894224]: Created trunk peer for '111.222.333.444:4569' Nov 20 16:55:38 DEBUG[-1109894224]: Expanded trunk '111.222.333.444:4569' to 6400 bytes Nov 20 16:55:40 DEBUG[-1109894224]: Received AST_CONTROL_PROGRESS on Zap/2-1 Nov 20 16:55:41 DEBUG[-1095144528]: Ooh, voice format changed to 1024 Nov 20 16:55:45 DEBUG[-1109894224]: Took Zap/2-1 off hook Nov 20 17:00:11 DEBUG[-1090942032]: Setting NAT on RTP to 0 Nov 20 17:00:11 DEBUG[-1090942032]: Stopping retransmission on '63662dfe6e7f826c7252e9ec66ab7724@192.168.1.9' of Request 102: Found Nov 20 17:00:20 DEBUG[-1090942032]: Auto destroying call '87dc40df1ff65be9@192.168.1.23' Nov 20 17:00:22 DEBUG[-1090942032]: Setting NAT on RTP to 0 Nov 20 17:00:22 DEBUG[-1090942032]: Stopping retransmission on '45374865706ee2eb44d7655b6543c2d9@192.168.1.9' of Request 102: Found Nov 20 17:00:35 DEBUG[-1090942032]: Auto destroying call '87dc40df1ff65be9@192.168.1.23' Nov 20 17:02:50 DEBUG[-1109894224]: Exception on 17, channel 2 Nov 20 17:02:50 DEBUG[-1109894224]: Got event On hook(1) on channel 2 (index 0) Nov 20 17:02:50 DEBUG[-1109894224]: disabled echo cancellation on channel 2 Nov 20 17:02:50 DEBUG[-1109894224]: Didn't get a frame from channel: Zap/2-1 Nov 20 17:02:50 DEBUG[-1109894224]: Bridge stops bridging channels Zap/2-1 and IAX2/provider-out/16385 Nov 20 17:02:50 DEBUG[-1109894224]: We're hanging up IAX2/provider-out/16385 now... Nov 20 17:02:50 DEBUG[-1109894224]: Exiting with DIALSTATUS=ANSWER. Nov 20 17:02:50 DEBUG[-1109894224]: cdr_mysql: inserting a CDR record. Nov 20 17:02:50 DEBUG[-1109894224]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2004-11-20 16:55:38','\"Cordless Phone\" <1234>','1234','90019090909090','local', 'Zap/2-1','IAX2/provider-out/16385','Dial','IAX2/user1@provider-out/19058289575',432,425,'ANSWERED',3,'Cordless Phone') Nov 20 17:02:50 DEBUG[-1109894224]: Hangup: channel: 2 index = 0, normal = 17, callwait = -1, thirdcall = -1 Nov 20 17:02:50 DEBUG[-1109894224]: disabled echo cancellation on channel 2 Nov 20 17:02:50 DEBUG[-1109894224]: Set option TDD MODE, value: OFF(0) on Zap/2-1 Nov 20 17:02:50 DEBUG[-1109894224]: Updated conferencing on 2, with 0 conference users Nov 20 17:02:53 DEBUG[-1109894224]: Exception on 17, channel 2 Nov 20 17:02:53 DEBUG[-1109894224]: Got event On hook(1) on channel 2 (index 0) Nov 20 17:02:53 DEBUG[-1109894224]: disabled echo cancellation on channel 2 Nov 20 17:02:53 DEBUG[-1109894224]: waitfordigit returned < 0... Nov 20 17:02:53 DEBUG[-1109894224]: Hangup: channel: 2 index = 0, normal = 17, callwait = -1, thirdcall = -1 Nov 20 17:02:53 DEBUG[-1109894224]: disabled echo cancellation on channel 2 Nov 20 17:02:53 DEBUG[-1109894224]: Set option TDD MODE, value: OFF(0) on Zap/2-1 Nov 20 17:02:53 DEBUG[-1109894224]: Updated conferencing on 2, with 0 conference users Nov 20 17:02:56 DEBUG[-1095144528]: Dropping unused iax2 trunk peer '111.222.333.444:4569' Nov 20 17:03:07 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 17:03:07 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 17:03:07 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 17:03:08 DEBUG[-1109894224]: DTMF digit: 1 on Zap/2-1 Nov 20 17:03:08 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 17:03:08 DEBUG[-1095144528]: Raw Hangup 111.222.333.444:4569, src=16385, dst=16387 Nov 20 17:03:08 DEBUG[-1095144528]: Raw Hangup 111.222.333.444:4569, src=16385, dst=16387 Nov 20 17:03:08 DEBUG[-1095144528]: Raw Hangup 111.222.333.444:4569, src=16385, dst=16387 Nov 20 17:03:08 DEBUG[-1095144528]: Raw Hangup 111.222.333.444:4569, src=16385, dst=16387 Nov 20 17:03:08 DEBUG[-1109894224]: DTMF digit: 0 on Zap/2-1 Nov 20 17:03:08 DEBUG[-1095144528]: Created trunk peer for '111.222.333.444:4569' Nov 20 17:03:08 DEBUG[-1095144528]: Raw Hangup 111.222.333.444:4569, src=16385, dst=16387 Nov 20 17:03:08 DEBUG[-1095144528]: Raw Hangup 111.222.333.444:4569, src=16385, dst=16387 Nov 20 17:03:08 DEBUG[-1095144528]: Raw Hangup 111.222.333.444:4569, src=16385, dst=16387 Nov 20 17:03:08 DEBUG[-1095144528]: Raw Hangup 111.222.333.444:4569, src=16385, dst=16387 Nov 20 17:03:08 DEBUG[-1109894224]: DTMF digit: 5 on Zap/2-1 Nov 20 17:03:08 DEBUG[-1109894224]: DTMF digit: 8 on Zap/2-1 Nov 20 17:03:08 DEBUG[-1109894224]: DTMF digit: 2 on Zap/2-1 Nov 20 17:03:09 DEBUG[-1109894224]: DTMF digit: 8 on Zap/2-1 Nov 20 17:03:09 DEBUG[-1109894224]: DTMF digit: 9 on Zap/2-1 Nov 20 17:03:09 DEBUG[-1109894224]: DTMF digit: 5 on Zap/2-1 Nov 20 17:03:09 DEBUG[-1109894224]: DTMF digit: 7 on Zap/2-1 Nov 20 17:03:09 DEBUG[-1095144528]: Immediately destroying 3, having received INVAL Nov 20 17:03:09 DEBUG[-1109894224]: DTMF digit: 5 on Zap/2-1 Nov 20 17:03:13 DEBUG[-1109894224]: Enabled echo cancellation on channel 2 Nov 20 17:03:13 DEBUG[-1109894224]: Made call 1 into trunk call 16384 Nov 20 17:03:13 DEBUG[-1109894224]: Expanded trunk '111.222.333.444:4569' to 6400 bytes Nov 20 17:03:16 DEBUG[-1109894224]: Received AST_CONTROL_PROGRESS on Zap/2-1 Nov 20 17:03:16 DEBUG[-1095144528]: Ooh, voice format changed to 1024 Nov 20 17:03:18 DEBUG[-1090942032]: Setting NAT on RTP to 0 Nov 20 17:03:18 DEBUG[-1090942032]: Stopping retransmission on '1553f9a5225aa136164b787d460d6105@192.168.1.9' of Request 102: Found Nov 20 17:03:22 DEBUG[-1109894224]: Took Zap/2-1 off hook Nov 20 17:03:28 DEBUG[-1090942032]: Auto destroying call '87dc40df1ff65be9@192.168.1.23' Nov 20 17:04:11 DEBUG[-1109894224]: Exception on 17, channel 2 Nov 20 17:04:11 DEBUG[-1109894224]: Got event Wink/Flash(3) on channel 2 (index 0) Nov 20 17:04:11 DEBUG[-1109894224]: Winkflash, index: 0, normal: 17, callwait: -1, thirdcall: -1 Nov 20 17:04:11 DEBUG[-1109894224]: Already have a dsp on Zap/2-2? Nov 20 17:04:11 DEBUG[-1109894224]: Swapping 2 and 0 Nov 20 17:04:11 DEBUG[-1109894224]: disabled echo cancellation on channel 2 Nov 20 17:04:11 DEBUG[-1109894224]: Updated conferencing on 2, with 0 conference users Nov 20 17:04:13 DEBUG[-1111995472]: Exception on 17, channel 2 Nov 20 17:04:13 DEBUG[-1111995472]: Got event On hook(1) on channel 2 (index 0) Nov 20 17:04:13 DEBUG[-1111995472]: Last flash was 1925 ms ago Nov 20 17:04:13 DEBUG[-1111995472]: Looks like a bounced flash, hanging up both calls on 2 Nov 20 17:04:13 DEBUG[-1111995472]: disabled echo cancellation on channel 2 Nov 20 17:04:13 DEBUG[-1111995472]: waitfordigit returned < 0... Nov 20 17:04:13 DEBUG[-1111995472]: Hangup: channel: 2 index = 0, normal = 17, callwait = -1, thirdcall = 21 Nov 20 17:04:13 DEBUG[-1111995472]: Swapping 2 and 0 Nov 20 17:04:13 DEBUG[-1111995472]: Released sub 2 of channel 2 Nov 20 17:04:13 DEBUG[-1111995472]: Call was incomplete, setting owner to NULL Nov 20 17:04:13 DEBUG[-1109894224]: Didn't get a frame from channel: Zap/2-1 Nov 20 17:04:13 DEBUG[-1109894224]: Bridge stops bridging channels Zap/2-1 and IAX2/provider-out/16384 Nov 20 17:04:13 DEBUG[-1109894224]: We're hanging up IAX2/provider-out/16384 now... Nov 20 17:04:13 DEBUG[-1109894224]: Exiting with DIALSTATUS=ANSWER. Nov 20 17:04:13 DEBUG[-1109894224]: cdr_mysql: inserting a CDR record. Nov 20 17:04:13 DEBUG[-1109894224]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES ('2004-11-20 17:03:13','\"Cordless Phone\" <1234>','1234','90019090909090','local', 'Zap/2-1','IAX2/provider-out/16384','Dial','IAX2/user1@provider-out/19058289575',60,51,'ANSWERED',3,'Cordless Phone') Nov 20 17:04:13 DEBUG[-1109894224]: Hangup: channel: 2 index = 0, normal = 17, callwait = -1, thirdcall = -1 Nov 20 17:04:13 DEBUG[-1109894224]: disabled echo cancellation on channel 2 Nov 20 17:04:13 DEBUG[-1109894224]: Set option TDD MODE, value: OFF(0) on Zap/2-1 Nov 20 17:04:13 DEBUG[-1109894224]: Updated conferencing on 2, with 0 conference users Nov 20 17:04:19 DEBUG[-1095144528]: Dropping unused iax2 trunk peer '111.222.333.444:4569' Nov 20 17:05:20 DEBUG[-1109894224]: Exception on 17, channel 2 Nov 20 17:05:20 DEBUG[-1109894224]: Got event On hook(1) on channel 2 (index 0) Nov 20 17:05:20 DEBUG[-1109894224]: disabled echo cancellation on channel 2 Nov 20 17:05:20 DEBUG[-1109894224]: waitfordigit returned < 0... Nov 20 17:05:20 DEBUG[-1109894224]: Hangup: channel: 2 index = 0, normal = 17, callwait = -1, thirdcall = -1 Nov 20 17:05:20 DEBUG[-1109894224]: disabled echo cancellation on channel 2 Nov 20 17:05:20 DEBUG[-1109894224]: Set option TDD MODE, value: OFF(0) on Zap/2-1 Nov 20 17:05:20 DEBUG[-1109894224]: Updated conferencing on 2, with 0 conference users Nov 20 17:07:09 DEBUG[-1095144528]: Immediately destroying 1, having received INVAL Nov 20 17:07:22 DEBUG[-1090942032]: Setting NAT on RTP to 0 Nov 20 17:07:22 DEBUG[-1090942032]: Stopping retransmission on '14eed84d185e95445fe20fff6c71bb98@192.168.1.9' of Request 102: Found Nov 20 17:07:31 DEBUG[-1090942032]: Auto destroying call '3c2670061ec1-6liv2cfevscu@192-168-1-20' Nov 20 17:09:44 DEBUG[-1090942032]: Setting NAT on RTP to 0 Nov 20 17:09:44 DEBUG[-1090942032]: Stopping retransmission on '5a53af9e6c59e8db5d26ae4c790d6bae@192.168.1.9' of Request 102: Found Nov 20 17:09:55 DEBUG[-1090942032]: Setting NAT on RTP to 0 Nov 20 17:09:55 DEBUG[-1090942032]: Stopping retransmission on '1d08156366dfd6c7084df22648d7cc09@192.168.1.9' of Request 102: Found Nov 20 17:10:00 DEBUG[-1090942032]: Auto destroying call '87dc40df1ff65be9@192.168.1.23' Nov 20 17:10:06 DEBUG[-1090942032]: Setting NAT on RTP to 0 Nov 20 17:10:06 DEBUG[-1090942032]: Stopping retransmission on '5dbeaaf933db32ca6269cf7b46f20b27@192.168.1.9' of Request 102: Found Nov 20 17:10:15 DEBUG[-1090942032]: Auto destroying call '87dc40df1ff65be9@192.168.1.23' Nov 20 17:10:17 DEBUG[-1090942032]: Setting NAT on RTP to 0 Nov 20 17:10:17 DEBUG[-1090942032]: Stopping retransmission on '37d063ed08813b2730b0231c6012716a@192.168.1.9' of Request 102: Found Nov 20 17:10:23 DEBUG[-1090942032]: Auto destroying call '3c2670049299-6liv2cfevscu@192-168-1-21' Nov 20 17:13:02 DEBUG[-1090942032]: Setting NAT on RTP to 0 Nov 20 17:13:02 DEBUG[-1090942032]: Stopping retransmission on '63a1baad39f98f524f8331c11d505755@192.168.1.9' of Request 102: Found Nov 20 17:13:09 DEBUG[-1090942032]: Auto destroying call '87dc40df1ff65be9@192.168.1.23'