Some inbound calls failing to get through

[barkode15]

Hello,
I've been having a strange problem that I'm trying my best to figure out. I have a DID with voip.ms that will randomly not pass calls to my PBX. The provider says everything is working on their side since the calls show up in their call log, they just never hit my PBX in a Flash box. They show as "No Answer" on their side. I usually find out this is happening by looking in their CDR and seeing a caller that has several calls lasting 0 seconds before they finally get through and have some time on a call.

The PBX is running Asterisk 1.4.21.2 on a Dynamic IP DSL line. I have sip_custom.conf set up to point to a dyndns address that follows the DSL IP. The local network is set correctly. I'm fairly certain it's not a DSL issue, my IP will stay the same for days and I can run pings for hours with 0% loss.

Does anyone have any suggestions of things to check? Also can anyone confirm the Reinvite behavior for a PBXiaF behind a NAT router should be set to no?

Thanks for any ideas anyone has.

 

[dswartz]

Not sure reinvite is an issue here. Are you sure they are not hitting your box? Check /var/log/asterisk/full for anything odd at that time?

 

[barkode15]

Thanks for the path to the full logs dswartz.
I checked all the logs for the 5 or 6 sets of failed calls from yesterday and couldn't find anything out of the ordinary.

Most had a hangup from a previous call right before the call that finally made it through to the pbx. It does look like the calls are getting lost somewhere between Voip.ms's box and mine.

Guess I'll run a ping again today and see if anything hiccups connection-wise.

 

[dswartz]

i wasn't looking for 'out of the ordinary', but anything at all during that window...

 

[jeffmac]

Not even an "unknown peer" message? Is voip.ms one of those providers that will send you a call from an IP address other than the one you registered with?

This was a problem with one of my providers and I had to add trunks for the other possible IPs they could send me a call from.

Just something else to check....

Jeff

 

[barkode15]

Here's one of the calls. First the Voip.ms CDR:

Time	Caller Number	My DID	Length	Cost
10/25/2010 16:55:37	908xxxxxxx	866451xxxx	4:39	0.1363
10/25/2010 16:55:34	908xxxxxxx	866451xxxx	0:00	0
10/25/2010 16:55:32	908xxxxxxx	866451xxxx	0:00	0
10/25/2010 16:55:21	908xxxxxxx	866451xxxx	0:00	0
10/25/2010 16:55:19	908xxxxxxx	866451xxxx	0:00	0
10/25/2010 16:55:16	908xxxxxxx	866451xxxx	0:00	0
10/25/2010 16:55:14	908xxxxxxx	866451xxxx	0:00	0
10/25/2010 16:55:11	908xxxxxxx	866451xxxx	0:00	0
10/25/2010 16:55:08	908xxxxxxx	866451xxxx	0:00	0
10/25/2010 16:55:06	908xxxxxxx	866451xxxx	0:00	0
10/25/2010 16:55:03	908xxxxxxx	866451xxxx	0:00	0

Then the Asterisk log from the same time period:

[2010-10-25 16:55:01] VERBOSE[9971] logger.c:   == Parsing '/etc/asterisk/manager.conf': [2010-10-25 16:55:01] VERBOSE[9971] logger.c: Found
[2010-10-25 16:55:01] VERBOSE[9971] logger.c:   == Parsing '/etc/asterisk/manager_additional.conf': [2010-10-25 16:55:01] VERBOSE[9971] logger.c: Found
[2010-10-25 16:55:01] VERBOSE[9971] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': [2010-10-25 16:55:01] VERBOSE[9971] logger.c: Found
[2010-10-25 16:55:01] VERBOSE[9971] logger.c:   == Manager 'admin' logged on from 127.0.0.1
[2010-10-25 16:55:02] VERBOSE[9971] logger.c:   == Manager 'admin' logged off from 127.0.0.1
Removed a repeat of the previous and next block
[2010-10-25 16:55:18] VERBOSE[9995] logger.c:   == Parsing '/etc/asterisk/manager.conf': [2010-10-25 16:55:18] VERBOSE[9995] logger.c: Found
[2010-10-25 16:55:18] VERBOSE[9995] logger.c:   == Parsing '/etc/asterisk/manager_additional.conf': [2010-10-25 16:55:18] VERBOSE[9995] logger.c: Found
[2010-10-25 16:55:18] VERBOSE[9995] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': [2010-10-25 16:55:18] VERBOSE[9995] logger.c: Found
[2010-10-25 16:55:18] VERBOSE[9995] logger.c:   == Manager 'admin' logged on from 127.0.0.1
[2010-10-25 16:55:18] VERBOSE[9995] logger.c:   == Manager 'admin' logged off from 127.0.0.1
[2010-10-25 16:55:22] VERBOSE[9998] logger.c:   == Parsing '/etc/asterisk/manager.conf': [2010-10-25 16:55:22] VERBOSE[9998] logger.c: Found
[2010-10-25 16:55:22] VERBOSE[9998] logger.c:   == Parsing '/etc/asterisk/manager_additional.conf': [2010-10-25 16:55:22] VERBOSE[9998] logger.c: Found
[2010-10-25 16:55:22] VERBOSE[9998] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': [2010-10-25 16:55:22] VERBOSE[9998] logger.c: Found
[2010-10-25 16:55:22] VERBOSE[9998] logger.c:   == Manager 'admin' logged on from 127.0.0.1
[2010-10-25 16:55:23] VERBOSE[9998] logger.c:   == Manager 'admin' logged off from 127.0.0.1
[2010-10-25 16:55:29] VERBOSE[10007] logger.c:   == Parsing '/etc/asterisk/manager.conf': [2010-10-25 16:55:29] VERBOSE[10007] logger.c: Found
[2010-10-25 16:55:29] VERBOSE[10007] logger.c:   == Parsing '/etc/asterisk/manager_additional.conf': [2010-10-25 16:55:29] VERBOSE[10007] logger.c: Found
[2010-10-25 16:55:29] VERBOSE[10007] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': [2010-10-25 16:55:29] VERBOSE[10007] logger.c: Found
[2010-10-25 16:55:29] VERBOSE[10007] logger.c:   == Manager 'admin' logged on from 127.0.0.1
[2010-10-25 16:55:31] VERBOSE[10007] logger.c:   == Manager 'admin' logged off from 127.0.0.1
[2010-10-25 16:55:37] VERBOSE[10016] logger.c:   == Parsing '/etc/asterisk/manager.conf': [2010-10-25 16:55:37] VERBOSE[10016] logger.c: Found
[2010-10-25 16:55:37] VERBOSE[10016] logger.c:   == Parsing '/etc/asterisk/manager_additional.conf': [2010-10-25 16:55:37] VERBOSE[10016] logger.c: Found
[2010-10-25 16:55:37] VERBOSE[10016] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': [2010-10-25 16:55:37] VERBOSE[10016] logger.c: Found
[2010-10-25 16:55:37] VERBOSE[10016] logger.c:   == Manager 'admin' logged on from 127.0.0.1
[2010-10-25 16:55:38] VERBOSE[10016] logger.c:   == Manager 'admin' logged off from 127.0.0.1
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [866451xxxx@from-trunk:1] Set("SIP/11xxxx-b780d618", "__FROM_DID=866451xxxx") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [866451xxxx@from-trunk:2] Gosub("SIP/11xxxx-b780d618", "app-blacklist-check|s|1") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@app-blacklist-check:1] LookupBlacklist("SIP/11xxxx-b780d618", "") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@app-blacklist-check:2] GotoIf("SIP/11xxxx-b780d618", "0?blacklisted") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@app-blacklist-check:3] Set("SIP/11xxxx-b780d618", "TESTAT=67.215.241.250>;tag=as077795c0") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@app-blacklist-check:4] GotoIf("SIP/11xxxx-b780d618", "1?hasat") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Goto (app-blacklist-check,s,7)
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@app-blacklist-check:7] Set("SIP/11xxxx-b780d618", "FROM_IP=67.215.241.250") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@app-blacklist-check:8] NoOp("SIP/11xxxx-b780d618", "Gateway IP is 67.215.241.250") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@app-blacklist-check:9] NoOp("SIP/11xxxx-b780d618", "IP Country Lookup in Progress...") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@app-blacklist-check:10] GotoIf("SIP/11xxxx-b780d618", "0?keepon") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@app-blacklist-check:11] AGI("SIP/11xxxx-b780d618", "nv-ipcountry.php|67.215.241.250") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Launched AGI Script /var/lib/asterisk/agi-bin/nv-ipcountry.php
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- AGI Script nv-ipcountry.php completed, returning 0
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@app-blacklist-check:12] GotoIf("SIP/11xxxx-b780d618", "0?blacklisted") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@app-blacklist-check:13] NoOp("SIP/11xxxx-b780d618", "** AUTHORIZED CALLER **") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@app-blacklist-check:14] Return("SIP/11xxxx-b780d618", "") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [866451xxxx@from-trunk:3] ExecIf("SIP/11xxxx-b780d618", "0 |Set|CALLERID(name)=908xxxxxxx") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [866451xxxx@from-trunk:4] Set("SIP/11xxxx-b780d618", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [866451xxxx@from-trunk:5] SetCallerPres("SIP/11xxxx-b780d618", "allowed_not_screened") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [866451xxxx@from-trunk:6] Goto("SIP/11xxxx-b780d618", "app-daynight|0|1") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Goto (app-daynight,0,1)
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [0@app-daynight:1] GotoIf("SIP/11xxxx-b780d618", "0?ivr-4|s|1:ivr-5|s|1") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Goto (ivr-5,s,1)
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@ivr-5:1] Set("SIP/11xxxx-b780d618", "MSG=custom/YouhavereachedPPCfirstpart&custom/ForSpanish2") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@ivr-5:2] Set("SIP/11xxxx-b780d618", "LOOPCOUNT=0") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@ivr-5:3] Set("SIP/11xxxx-b780d618", "__DIR-CONTEXT=") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@ivr-5:4] Set("SIP/11xxxx-b780d618", "_IVR_CONTEXT_ivr-5=") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@ivr-5:5] Set("SIP/11xxxx-b780d618", "_IVR_CONTEXT=ivr-5") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@ivr-5:6] GotoIf("SIP/11xxxx-b780d618", "0?begin") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@ivr-5:7] Answer("SIP/11xxxx-b780d618", "") in new stack
[2010-10-25 16:55:38] VERBOSE[10024] logger.c:     -- Executing [s@ivr-5:8] Wait("SIP/11xxxx-b780d618", "1") in new stack
[2010-10-25 16:55:39] VERBOSE[10024] logger.c:     -- Executing [s@ivr-5:9] Set("SIP/11xxxx-b780d618", "TIMEOUT(digit)=3") in new stack
[2010-10-25 16:55:39] VERBOSE[10024] logger.c:     -- Digit timeout set to 3
[2010-10-25 16:55:39] VERBOSE[10024] logger.c:     -- Executing [s@ivr-5:10] Set("SIP/11xxxx-b780d618", "TIMEOUT(response)=1") in new stack
[2010-10-25 16:55:39] VERBOSE[10024] logger.c:     -- Response timeout set to 1
[2010-10-25 16:55:39] VERBOSE[10024] logger.c:     -- Executing [s@ivr-5:11] Set("SIP/11xxxx-b780d618", "__IVR_RETVM=") in new stack
[2010-10-25 16:55:39] VERBOSE[10024] logger.c:     -- Executing [s@ivr-5:12] ExecIf("SIP/11xxxx-b780d618", "1|Background|custom/YouhavereachedPPCfirstpart&custom/ForSpanish2") in new stack

So the call should get through at 55:03 but doesn't. The caller kept trying until they finally got through at 55:37. I believe I was sitting on the admin page at the time which I guess would explain the log ons and offs before the call comes in.

Thanks for taking a look guys.

 

[jeffmac]

Hmmm - there's certainly no indication there.

Maybe its time for a SIP DEBUG for their IP address and see if there's anything getting to you. If there it may give you a lead.

If there isn't it may be time to have a deeper discussion with your provider....

Jeff