Dropped Calls

Discussion in 'General' started by micropat, Jul 8, 2010.

  1. micropat

    Joined:
    Apr 28, 2010
    Messages:
    19
    Likes Received:
    0
    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.
     
  2. hinzinho

    Joined:
    Sep 18, 2009
    Messages:
    461
    Likes Received:
    0
  3. micropat

    Joined:
    Apr 28, 2010
    Messages:
    19
    Likes Received:
    0
    One thing I forgot to mention is that the carrier provides a SIP trunk.
     
  4. thorpe5278

    Joined:
    Jan 10, 2010
    Messages:
    50
    Likes Received:
    0
    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.
     
  5. thorpe5278

    Joined:
    Jan 10, 2010
    Messages:
    50
    Likes Received:
    0
    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.
     
  6. dicko

    Joined:
    Oct 24, 2008
    Messages:
    4,099
    Likes Received:
    0
    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
     
  7. thorpe5278

    Joined:
    Jan 10, 2010
    Messages:
    50
    Likes Received:
    0
    Thanks Dicko is there anything I shouldl grep or look for in the logs?
     
  8. dicko

    Joined:
    Oct 24, 2008
    Messages:
    4,099
    Likes Received:
    0
    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.
     
  9. thorpe5278

    Joined:
    Jan 10, 2010
    Messages:
    50
    Likes Received:
    0
    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.
     
  10. dicko

    Joined:
    Oct 24, 2008
    Messages:
    4,099
    Likes Received:
    0
    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
     
  11. thorpe5278

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

    Joined:
    Oct 24, 2008
    Messages:
    4,099
    Likes Received:
    0
    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
     
  13. thorpe5278

    Joined:
    Jan 10, 2010
    Messages:
    50
    Likes Received:
    0
    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.
     
  14. thorpe5278

    Joined:
    Jan 10, 2010
    Messages:
    50
    Likes Received:
    0
    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?
     
  15. dicko

    Joined:
    Oct 24, 2008
    Messages:
    4,099
    Likes Received:
    0
  16. thorpe5278

    Joined:
    Jan 10, 2010
    Messages:
    50
    Likes Received:
    0
    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
     
  17. dicko

    Joined:
    Oct 24, 2008
    Messages:
    4,099
    Likes Received:
    0
    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 )
     
  18. hantuketawa

    Joined:
    Jul 22, 2011
    Messages:
    2
    Likes Received:
    0
    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
     

Share This Page