Intermittent Inbound busy signal

gsi_Nathan · May 23, 2011, 9:27pm

Running Asterisk 1.6.2.17.2 on FreePBX 2.7.0.10

We have 2 in bound sipstation trunks, and 2 analog lines on a DADHI card. All inbound calls endup in our IVR regardless of source. Outbound calls are working just fine.

On occasion, and very randomly a call will come in from our sip trunk, get picked up by freepbx then goto a busy signal. I grabbed a few snippets from the logs, The first shows a call comming in and going to IVR.

[May 23 09:31:36] VERBOSE[3451] netsock.c:   == Using SIP RTP TOS bits 184
[May 23 09:31:36] VERBOSE[3451] netsock.c:   == Using SIP RTP CoS mark 5
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [<InboundPhoneNumber>@from-pstn:1] NoOp("SIP/fpbx-1-d62e8a55-00000242", "Catch-All DID Match - Found <InboundPhoneNumber> - You probably want a DID for this.") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [<InboundPhoneNumber>@from-pstn:2] Goto("SIP/fpbx-1-d62e8a55-00000242", "ext-did,s,1") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Goto (ext-did,s,1)
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ext-did:1] Set("SIP/fpbx-1-d62e8a55-00000242", "__FROM_DID=s") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ext-did:2] ExecIf("SIP/fpbx-1-d62e8a55-00000242", "0 ?Set(CALLERID(name)=+<MyMobileNumber>)") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ext-did:3] SetMusicOnHold("SIP/fpbx-1-d62e8a55-00000242", "Other") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ext-did:4] Set("SIP/fpbx-1-d62e8a55-00000242", "__MOHCLASS=Other") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ext-did:5] Set("SIP/fpbx-1-d62e8a55-00000242", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ext-did:6] Set("SIP/fpbx-1-d62e8a55-00000242", "CALLERPRES()=allowed_not_screened") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ext-did:7] Goto("SIP/fpbx-1-d62e8a55-00000242", "ivr-3,s,1") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Goto (ivr-3,s,1)
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ivr-3:1] Set("SIP/fpbx-1-d62e8a55-00000242", "MSG=custom/MainGreeting") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ivr-3:2] Set("SIP/fpbx-1-d62e8a55-00000242", "LOOPCOUNT=0") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ivr-3:3] Set("SIP/fpbx-1-d62e8a55-00000242", "__DIR-CONTEXT=default") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ivr-3:4] Set("SIP/fpbx-1-d62e8a55-00000242", "_IVR_CONTEXT_ivr-3=") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ivr-3:5] Set("SIP/fpbx-1-d62e8a55-00000242", "_IVR_CONTEXT=ivr-3") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ivr-3:6] GotoIf("SIP/fpbx-1-d62e8a55-00000242", "0?begin") in new stack
[May 23 09:31:36] VERBOSE[31079] pbx.c:     -- Executing [s@ivr-3:7] Answer("SIP/fpbx-1-d62e8a55-00000242", "") in new stack
[May 23 09:31:37] VERBOSE[31079] pbx.c:     -- Executing [s@ivr-3:8] Wait("SIP/fpbx-1-d62e8a55-00000242", "1") in new stack
[May 23 09:31:38] VERBOSE[31079] pbx.c:     -- Executing [s@ivr-3:9] Set("SIP/fpbx-1-d62e8a55-00000242", "TIMEOUT(digit)=3") in new stack
[May 23 09:31:38] VERBOSE[31079] func_timeout.c:     -- Digit timeout set to 3.000
[May 23 09:31:38] VERBOSE[31079] pbx.c:     -- Executing [s@ivr-3:10] Set("SIP/fpbx-1-d62e8a55-00000242", "TIMEOUT(response)=10") in new stack
[May 23 09:31:38] VERBOSE[31079] func_timeout.c:     -- Response timeout set to 10.000
[May 23 09:31:38] VERBOSE[31079] pbx.c:     -- Executing [s@ivr-3:11] Set("SIP/fpbx-1-d62e8a55-00000242", "__IVR_RETVM=") in new stack
[May 23 09:31:38] VERBOSE[31079] pbx.c:     -- Executing [s@ivr-3:12] ExecIf("SIP/fpbx-1-d62e8a55-00000242", "1?Background(custom/MainGreeting)") in new stack
[May 23 09:31:38] VERBOSE[31079] file.c:     -- <SIP/fpbx-1-d62e8a55-00000242> Playing 'custom/MainGreeting.slin' (language 'en')
[May 23 09:31:43] VERBOSE[31079] pbx.c:   == Spawn extension (ivr-3, s, 12) exited non-zero on 'SIP/fpbx-1-d62e8a55-00000242'
[May 23 09:31:43] VERBOSE[31079] pbx.c:     -- Executing [h@ivr-3:1] Hangup("SIP/fpbx-1-d62e8a55-00000242", "") in new stack
[May 23 09:31:43] VERBOSE[31079] pbx.c:   == Spawn extension (ivr-3, h, 1) exited non-zero on 'SIP/fpbx-1-d62e8a55-00000242'

This shows call that went to busy signal after a few rings.

[May 23 09:30:40] VERBOSE[3451] netsock.c:   == Using SIP RTP TOS bits 184
[May 23 09:30:40] VERBOSE[3451] netsock.c:   == Using SIP RTP CoS mark 5
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [<InboundPhoneNumber>@from-pstn:1] NoOp("SIP/fpbx-1-d62e8a55-00000241", "Catch-All DID Match - Found <InboundPhoneNumber> - You probably want a DID for this.") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [<InboundPhoneNumber>@from-pstn:2] Goto("SIP/fpbx-1-d62e8a55-00000241", "ext-did,s,1") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Goto (ext-did,s,1)
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ext-did:1] Set("SIP/fpbx-1-d62e8a55-00000241", "__FROM_DID=s") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ext-did:2] ExecIf("SIP/fpbx-1-d62e8a55-00000241", "0 ?Set(CALLERID(name)=+<MyMobileNumber>)") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ext-did:3] SetMusicOnHold("SIP/fpbx-1-d62e8a55-00000241", "Other") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ext-did:4] Set("SIP/fpbx-1-d62e8a55-00000241", "__MOHCLASS=Other") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ext-did:5] Set("SIP/fpbx-1-d62e8a55-00000241", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ext-did:6] Set("SIP/fpbx-1-d62e8a55-00000241", "CALLERPRES()=allowed_not_screened") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ext-did:7] Goto("SIP/fpbx-1-d62e8a55-00000241", "ivr-3,s,1") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Goto (ivr-3,s,1)
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ivr-3:1] Set("SIP/fpbx-1-d62e8a55-00000241", "MSG=custom/MainGreeting") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ivr-3:2] Set("SIP/fpbx-1-d62e8a55-00000241", "LOOPCOUNT=0") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ivr-3:3] Set("SIP/fpbx-1-d62e8a55-00000241", "__DIR-CONTEXT=default") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ivr-3:4] Set("SIP/fpbx-1-d62e8a55-00000241", "_IVR_CONTEXT_ivr-3=") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ivr-3:5] Set("SIP/fpbx-1-d62e8a55-00000241", "_IVR_CONTEXT=ivr-3") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ivr-3:6] GotoIf("SIP/fpbx-1-d62e8a55-00000241", "0?begin") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [s@ivr-3:7] Answer("SIP/fpbx-1-d62e8a55-00000241", "") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:   == Spawn extension (ivr-3, s, 7) exited non-zero on 'SIP/fpbx-1-d62e8a55-00000241'
[May 23 09:30:45] VERBOSE[31067] pbx.c:     -- Executing [h@ivr-3:1] Hangup("SIP/fpbx-1-d62e8a55-00000241", "") in new stack
[May 23 09:30:45] VERBOSE[31067] pbx.c:   == Spawn extension (ivr-3, h, 1) exited non-zero on 'SIP/fpbx-1-d62e8a55-00000241'

Any ideas of what might be causing this?

gsi_Nathan · May 24, 2011, 12:36am

After additional testing it appears that the line will only report a busy signal on the first call, the second and any subsequent calls coming in over the next few minutes are fine. So i’m thinking that this is some sort of a SIP trunk issue.

Here is one of our peer records for our SIP trunk.


disallow=all
allow=ulaw
context=from-pstn&from-pstn
type=peer
insecure=very
qualify=yes
sendrpid=yes
trustrpid=yes
dtmfmode=rfc2833
username=<USER>
secret=<PW>
host=trunk1.phonebooth.net

BroColby · October 17, 2011, 4:06am

I am having the same issue.

Were you ever able to isolate the cause? I was thinking it was with the two routes setup (trunk1.phonebooth.net vs. trunk2.phonebooth.net). When I would see these calls in the call report, trunk2 always seemed to be the working trunk 98% of the time, so I disabled trunk1. However, I just experienced the same problem with only trunk2 enabled.

gsi_Nathan · October 17, 2011, 4:02pm

Ended up changing SIP Providers and that seems to have fixed it.

BroColby · October 17, 2011, 7:32pm

Who did you switch to?

gsi_Nathan · October 17, 2011, 7:37pm

Switched to bandwidth.com they own sipstation but it’s a seperate business unit. Got much better support from them as well.

http://bandwidth.com/sip-trunking/