Dropped Calls

micropat

Joined
Apr 28, 2010
Messages
19
Likes
0
Points
0
#1
I am having an issue with dropped calls and I'm not convinced that the issue is coming from the carrier. In the log (see below), I found this message: Error deleting key from database. I would like to find out what is causing this error and either fix it or definatively point the finger at the carrier. Any help would be appreciated.

[Jul 7 17:27:12] VERBOSE[14516] logger.c: -- Executing [s@macro-dial:27] GotoIf("Local/150@from-internal-9567,2", "1?a32:a35") in new stack
[Jul 7 17:27:12] VERBOSE[14516] logger.c: -- Goto (macro-dial,s,28)
[Jul 7 17:27:12] DEBUG[14516] app_macro.c: Executed application: GotoIf
[Jul 7 17:27:12] VERBOSE[14516] logger.c: -- Executing [s@macro-dial:28] Set("Local/150@from-internal-9567,2", "CT_EXTEN=150") in new stack
[Jul 7 17:27:12] DEBUG[14516] app_macro.c: Executed application: Set
[Jul 7 17:27:12] VERBOSE[14516] logger.c: -- Executing [s@macro-dial:29] Set("Local/150@from-internal-9567,2", "DB(CALLTRACE/150)=8012709500") in new stack
[Jul 7 17:27:12] DEBUG[14516] app_macro.c: Executed application: Set
[Jul 7 17:27:12] VERBOSE[14516] logger.c: -- Executing [s@macro-dial:30] Goto("Local/150@from-internal-9567,2", "s|a42") in new stack
[Jul 7 17:27:12] VERBOSE[14516] logger.c: -- Goto (macro-dial,s,38)
[Jul 7 17:27:12] DEBUG[14516] app_macro.c: Executed application: Goto
[Jul 7 17:27:12] VERBOSE[14516] logger.c: -- Executing [s@macro-dial:38] Dial("Local/150@from-internal-9567,2", "SIP/150|20|trM(auto-blkvm)") in new stack
[Jul 7 17:27:12] NOTICE[14516] app_dial.c: Hey! chan Local/150@from-internal-9567,2's context='macro-dial', and exten='s'
[Jul 7 17:27:12] VERBOSE[14516] logger.c: -- Called 150
[Jul 7 17:27:12] VERBOSE[14512] logger.c: -- Local/150@from-internal-9567,1 is ringing
[Jul 7 17:27:13] VERBOSE[14516] logger.c: -- SIP/150-08bcfed8 is ringing
[Jul 7 17:27:16] VERBOSE[14516] logger.c: -- SIP/150-08bcfed8 answered Local/150@from-internal-9567,2
[Jul 7 17:27:16] VERBOSE[14516] logger.c: -- Executing [s@macro-auto-blkvm:1] Set("SIP/150-08bcfed8", "__MACRO_RESULT=") in new stack
[Jul 7 17:27:16] DEBUG[14516] app_macro.c: Executed application: Set
[Jul 7 17:27:16] VERBOSE[14516] logger.c: -- Executing [s@macro-auto-blkvm:2] DBdel("SIP/150-08bcfed8", "BLKVM/250/SIP/Velocity-08c00df8") in new stack
[Jul 7 17:27:16] VERBOSE[14516] logger.c: -- DBdel: family=BLKVM, key=250/SIP/Velocity-08c00df8
[Jul 7 17:27:16] DEBUG[14516] app_macro.c: Executed application: dbDel
[Jul 7 17:27:16] DEBUG[14516] app_dial.c: Macro exited with status 0
[Jul 7 17:27:16] VERBOSE[14512] logger.c: -- Local/150@from-internal-9567,1 answered SIP/Velocity-08c00df8
[Jul 7 17:27:16] VERBOSE[14512] logger.c: -- Executing [s@macro-auto-blkvm:1] Set("Local/150@from-internal-9567,1", "__MACRO_RESULT=") in new stack
[Jul 7 17:27:16] DEBUG[14512] app_macro.c: Executed application: Set
[Jul 7 17:27:16] VERBOSE[14512] logger.c: -- Executing [s@macro-auto-blkvm:2] DBdel("Local/150@from-internal-9567,1", "BLKVM/250/SIP/Velocity-08c00df8") in new stack
[Jul 7 17:27:16] VERBOSE[14512] logger.c: -- DBdel: family=BLKVM, key=250/SIP/Velocity-08c00df8
[Jul 7 17:27:16] VERBOSE[14512] logger.c: -- DBdel: Error deleting key from database.
[Jul 7 17:27:16] DEBUG[14512] app_macro.c: Executed application: dbDel
[Jul 7 17:27:16] DEBUG[14512] app_dial.c: Macro exited with status 0
[Jul 7 17:27:16] VERBOSE[14516] logger.c: -- Executing [h@macro-dial:1] Macro("Local/150@from-internal-9567,2", "hangupcall") in new stack
[Jul 7 17:27:16] VERBOSE[14516] logger.c: -- Executing [s@macro-hangupcall:1] GotoIf("Local/150@from-internal-9567,2", "1?skiprg") in new stack
[Jul 7 17:27:16] VERBOSE[14516] logger.c: -- Goto (macro-hangupcall,s,4)
[Jul 7 17:27:16] DEBUG[14516] app_macro.c: Executed application: GotoIf
[Jul 7 17:27:16] VERBOSE[14516] logger.c: -- Executing [s@macro-hangupcall:4] GotoIf("Local/150@from-internal-9567,2", "1?skipblkvm") in new stack
[Jul 7 17:27:16] VERBOSE[14516] logger.c: -- Goto (macro-hangupcall,s,7)
[Jul 7 17:27:16] DEBUG[14516] app_macro.c: Executed application: GotoIf
[Jul 7 17:27:16] VERBOSE[14516] logger.c: -- Executing [s@macro-hangupcall:7] GotoIf("Local/150@from-internal-9567,2", "1?theend") in new stack
[Jul 7 17:27:16] VERBOSE[14516] logger.c: -- Goto (macro-hangupcall,s,9)
[Jul 7 17:27:16] DEBUG[14516] app_macro.c: Executed application: GotoIf
[Jul 7 17:27:16] VERBOSE[14516] logger.c: -- Executing [s@macro-hangupcall:9] Hangup("Local/150@from-internal-9567,2", "") in new stack
[Jul 7 17:27:16] VERBOSE[14516] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'Local/150@from-internal-9567,2' in macro 'hangupcall'
[Jul 7 17:27:16] VERBOSE[14516] logger.c: == Spawn h extension (macro-dial, h, 1) exited non-zero on 'Local/150@from-internal-9567,2'
[Jul 7 17:27:16] VERBOSE[14516] logger.c: == Spawn extension (macro-dial, s, 38) exited non-zero on 'Local/150@from-internal-9567,2' in macro 'dial'
[Jul 7 17:27:16] VERBOSE[14516] logger.c: == Spawn extension (from-internal, 150, 18) exited non-zero on 'Local/150@from-internal-9567,2'
[Jul 7 17:27:17] VERBOSE[14512] logger.c: -- Executing [h@macro-dial:1] Macro("SIP/Velocity-08c00df8", "hangupcall") in new stack
[Jul 7 17:27:17] VERBOSE[14512] logger.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/Velocity-08c00df8", "1?skiprg") in new stack
[Jul 7 17:27:17] VERBOSE[14512] logger.c: -- Goto (macro-hangupcall,s,4)
[Jul 7 17:27:17] DEBUG[14512] app_macro.c: Executed application: GotoIf
[Jul 7 17:27:17] VERBOSE[14512] logger.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/Velocity-08c00df8", "0?skipblkvm") in new stack
[Jul 7 17:27:17] DEBUG[14512] app_macro.c: Executed application: GotoIf
[Jul 7 17:27:17] VERBOSE[14512] logger.c: -- Executing [s@macro-hangupcall:5] NoOp("SIP/Velocity-08c00df8", "Cleaning Up Block VM Flag: BLKVM/250/SIP/Velocity-08c00df8") in new stack
[Jul 7 17:27:17] DEBUG[14512] app_macro.c: Executed application: Noop
[Jul 7 17:27:17] VERBOSE[14512] logger.c: -- Executing [s@macro-hangupcall:6] DBdel("SIP/Velocity-08c00df8", "BLKVM/250/SIP/Velocity-08c00df8") in new stack
[Jul 7 17:27:17] VERBOSE[14512] logger.c: -- DBdel: family=BLKVM, key=250/SIP/Velocity-08c00df8
[Jul 7 17:27:17] VERBOSE[14512] logger.c: -- DBdel: Error deleting key from database.
 

hinzinho

Joined
Sep 18, 2009
Messages
461
Likes
0
Points
0
#2

micropat

Joined
Apr 28, 2010
Messages
19
Likes
0
Points
0
#3
One thing I forgot to mention is that the carrier provides a SIP trunk.
 

thorpe5278

Joined
Jan 10, 2010
Messages
50
Likes
0
Points
0
#4
I am having the same problem and I also use SIP trunks. I dont have any cards or such for voice in my system. Callers can be on the phone for a while and then the call gets dropped.
 

thorpe5278

Joined
Jan 10, 2010
Messages
50
Likes
0
Points
0
#5
I have the same problem and use SIP trunks from Verizon. I have other deplyments that use different providers and still have the same problem.
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#6
A "dropped call" on a sip trunk is either that you have a network problem or a VOIP server problem..

in asterisk do:


sip debug ip < the culprit>

and

rtp debug ip <the same dude>

will probably demonstrate what got dropped first, my guess it was the rtp connection failed/timed out if the SIP connection was successful in the first place.

gotta be quick to catch that, but /var/log/asterisk/full will contain all that stuff for forensic analysis, complete with a time stamp.

dicko
 

thorpe5278

Joined
Jan 10, 2010
Messages
50
Likes
0
Points
0
#7
Thanks Dicko is there anything I shouldl grep or look for in the logs?
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#8
At the point the call drops, there will be a discontinuity, probably in the rtp stream, but perhaps SIP will bitch and whine also. Find that discontinuity by grepping the time stamp (liberally) piped through less, that will be shit-loads, but you can incrementally isolate the grep to the few seconds when it happened.

If it drops peremptorily, look to your router's ability to keep connections up as necessary.
 

thorpe5278

Joined
Jan 10, 2010
Messages
50
Likes
0
Points
0
#9
Well if anyone is intrested we found out our problem. One of the MP3 files that played for our customers holding in a queue had some issues and was causing asterisk hiccup dropping calls.
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#10
There are many posts here as to how mp3 should be formatted, but for your benefit you should use good old .wav files to save cpu cycles, the acceptable format is also well documented
 

thorpe5278

Joined
Jan 10, 2010
Messages
50
Likes
0
Points
0
#11
Thanks I will look for that information. Also have to give credit to PaloSanto their support found the problem for me.
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#12
Then without denying our sponsors income, please share the solution, this is a two way forum, you asked here first , you have a solution, you should give resolution, does that not make sense? I originally answered you three days ago, that you cared not to close this issue is just plain rude, no?

dicko
 

thorpe5278

Joined
Jan 10, 2010
Messages
50
Likes
0
Points
0
#13
Well we found the problem that was a bad MP3 not sure what it was. Our solution was to remove the file and use another one. I am still trying to figure out what was wrong with the MP3 file. I will let everyone know what I find out.
 

thorpe5278

Joined
Jan 10, 2010
Messages
50
Likes
0
Points
0
#14
Well that did fix the asterisk crashing problem but I still continue to have dropped calls. Any ideas when I should look for in the SIP debug files?
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#15

thorpe5278

Joined
Jan 10, 2010
Messages
50
Likes
0
Points
0
#16
Well I didnt have SIP debug running at the time but this is what showed in the log. The call started at 16:30 and about 15min later it dropped. You can see between 16:31 and then it goes to 16.46 when the call drops.


[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-dialout-trunk:4] Set("SIP/8231-000013bd", "DIAL_NUMBER=18778738017") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-dialout-trunk:3] GotoIf("SIP/8231-000013bd", "0?disabletrunk|1") in new stack
[Jul 22 16:46:49] DEBUG[5603] func_db.c: DB: AMPUSER/8231/pinless not found in database.
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-dialout-trunk:2] GosubIf("SIP/8231-000013bd", "0?sub-pincheck|s|1") in new stack
[Jul 22 16:46:49] DEBUG[5603] func_db.c: DB: AMPUSER/8231/pinless not found in database.
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-dialout-trunk:1] Set("SIP/8231-000013bd", "DIAL_TRUNK=4") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [918778738017@from-internal:4] Macro("SIP/8231-000013bd", "dialout-trunk|4|18778738017||") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-record-enable:5] MacroExit("SIP/8231-000013bd", "") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-record-enable:4] AGI("SIP/8231-000013bd", "recordingcheck|20100722-164649|1279835209.7531") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-record-enable:1] GotoIf("SIP/8231-000013bd", "1?check") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [918778738017@from-internal:3] Macro("SIP/8231-000013bd", "record-enable|8231|OUT|") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [918778738017@from-internal:2] Set("SIP/8231-000013bd", "_NODEST=") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-user-callerid:19] NoOp("SIP/8231-000013bd", "Using CallerID "Tim Archuleta" <8231>") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-user-callerid:10] GotoIf("SIP/8231-000013bd", "1?continue") in new stack
[Jul 22 16:46:49] DEBUG[5603] func_db.c: DB: AMPUSER/8231/language not found in database.
[Jul 22 16:46:49] DEBUG[5603] func_db.c: DB: AMPUSER/8231/language not found in database.
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-user-callerid:9] ExecIf("SIP/8231-000013bd", "0|Set|CHANNEL(language)=") in new stack
[Jul 22 16:46:49] DEBUG[5603] func_db.c: DB: AMPUSER/8231/language not found in database.
[Jul 22 16:46:49] DEBUG[5603] func_db.c: DB: AMPUSER/8231/language not found in database.
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-user-callerid:8] Set("SIP/8231-000013bd", "CALLERID(all)="Tim Archuleta" <8231>") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-user-callerid:7] Set("SIP/8231-000013bd", "AMPUSERCID=8231") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-user-callerid:6] GotoIf("SIP/8231-000013bd", "0?report") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-user-callerid:5] Set("SIP/8231-000013bd", "AMPUSERCIDNAME=Tim Archuleta") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-user-callerid:4] Set("SIP/8231-000013bd", "AMPUSER=8231") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-user-callerid:3] ExecIf("SIP/8231-000013bd", "1|Set|REALCALLERIDNUM=8231") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-user-callerid:2] GotoIf("SIP/8231-000013bd", "0?report") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [s@macro-user-callerid:1] Set("SIP/8231-000013bd", "AMPUSER=8231") in new stack
[Jul 22 16:46:49] VERBOSE[5603] logger.c: -- Executing [918778738017@from-internal:1] Macro("SIP/8231-000013bd", "user-callerid|SKIPTTL|") in new stack
[Jul 22 16:46:46] VERBOSE[5336] logger.c: == Spawn extension (from-internal, 918778738017, 4) exited non-zero on 'SIP/8231-0000134f'
[Jul 22 16:46:46] VERBOSE[5336] logger.c: == Spawn extension (macro-dialout-trunk, s, 19) exited non-zero on 'SIP/8231-0000134f' in macro 'dialout-trunk'
[Jul 22 16:46:46] VERBOSE[5336] logger.c: == Spawn h extension (macro-dialout-trunk, h, 1) exited non-zero on 'SIP/8231-0000134f'
[Jul 22 16:46:46] VERBOSE[5336] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/8231-0000134f' in macro 'hangupcall'
[Jul 22 16:46:46] VERBOSE[5336] logger.c: -- Executing [s@macro-hangupcall:9] Hangup("SIP/8231-0000134f", "") in new stack
[Jul 22 16:46:46] VERBOSE[5336] logger.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/8231-0000134f", "1?theend") in new stack
[Jul 22 16:46:46] VERBOSE[5336] logger.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/8231-0000134f", "1?skipblkvm") in new stack
[Jul 22 16:46:46] VERBOSE[5336] logger.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/8231-0000134f", "1?skiprg") in new stack
[Jul 22 16:46:46] VERBOSE[5336] logger.c: -- Executing [h@macro-dialout-trunk:1] Macro("SIP/8231-0000134f", "hangupcall|") in new stack
[Jul 22 16:31:35] VERBOSE[5336] logger.c: -- SIP/VerizonSIP-00001350 answered SIP/8231-0000134f
[Jul 22 16:31:35] VERBOSE[5336] logger.c: -- SIP/VerizonSIP-00001350 is making progress passing it to SIP/8231-0000134f
[Jul 22 16:31:33] NOTICE[5336] app_dial.c: Hey! chan SIP/8231-0000134f's context='macro-dialout-trunk', and exten='s'
[Jul 22 16:31:33] VERBOSE[5336] logger.c: -- Executing [s@macro-dialout-trunk:19] Dial("SIP/8231-0000134f", "SIP/VerizonSIP/18778738017|300|Ww") in new stack
[Jul 22 16:31:33] VERBOSE[5336] logger.c: -- Executing [s@macro-dialout-trunk:18] GotoIf("SIP/8231-0000134f", "0?customtrunk") in new stack
[Jul 22 16:31:33] VERBOSE[5336] logger.c: -- Executing [s@macro-dialout-trunk:17] GotoIf("SIP/8231-0000134f", "0?bypass|1") in new stack
[Jul 22 16:31:33] VERBOSE[5336] logger.c: -- Executing [s@macro-dialout-trunk-predial-hook:1] MacroExit("SIP/8231-0000134f", "") in new stack
[Jul 22 16:31:33] VERBOSE[5336] logger.c: -- Executing [s@macro-dialout-trunk:16] Macro("SIP/8231-0000134f", "dialout-trunk-predial-hook|") in new stack
[Jul 22 16:31:33] VERBOSE[5336] logger.c: -- Executing [s@macro-dialout-trunk:15] ExecIf("SIP/8231-0000134f", "0|Set|DIAL_TRUNK_OPTIONS=M(setmusic^)Ww") in new stack
 

dicko

Joined
Oct 24, 2008
Messages
4,099
Likes
0
Points
0
#17
The missing data that might help you is I suggested the rtp debug info and the sip debug info. There is no SIP debug info in your post, nor any RTP info. (you can add rtcp (real time control protocol) for completeness)

I told you generally how just allow those debugs to the ip of the connection in question.

I assume you see them linearly in the log, no? they will be probably around 16:46 the SIP debug info will NOT be timestamped, but they will be temporally in sequence

(please don't post those logs without isolating very specifically the "point of discontinuity" i.e. just before the call dropped as they will be VERY BIG )
 

hantuketawa

Joined
Jul 22, 2011
Messages
2
Likes
0
Points
0
#18
This is NAT issue. edit file
[root@efax asterisk]# nano sip_general_additional.conf. change values line below:

1. canreinvite=update
2. nat=yes
3. externip=x.x.x.x
4. localnet=y.y.y.y/z.z.z.z
5. localnet=r.r.r.r/q

point 1 is very important, and if current already can call trough sip-trunk point 2-5 skipped.

that's worked for me.
Rgds,
Nad
 

Members online

Latest posts

Forum statistics

Threads
30,915
Messages
130,920
Members
17,594
Latest member
knethardsolutions
Top