I'm having some issues with calls jumping over to a failover trunk in certain situations. I'm trying to track down what the cause is, I think it has to do with fax detection. Hopefully someone here can help.
Code sample - I've scrubbed out phone numbers for privacy.
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [<mynumber>@from-trunk:1] Set("SIP/bluenote-08d001f8", "__FROM_DID=<mynumber>") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [<mynumber>@from-trunk:2] Gosub("SIP/bluenote-08d001f8", "app-blacklist-check|s|1") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [s@app-blacklist-check:1] LookupBlacklist("SIP/bluenote-08d001f8", "") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [s@app-blacklist-check:2] GotoIf("SIP/bluenote-08d001f8", "0?blacklisted") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [s@app-blacklist-check:3] Return("SIP/bluenote-08d001f8", "") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [<mynumber>@from-trunk:3] GotoIf("SIP/bluenote-08d001f8", "1 ?cidok") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Goto (from-trunk,<mynumber>,5)
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [<mynumber>@from-trunk:5] NoOp("SIP/bluenote-08d001f8", "CallerID is "<customernumber>" <<customernumber>>") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [<mynumber>@from-trunk:6] Set("SIP/bluenote-08d001f8", "FAX_RX=disabled") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [<mynumber>@from-trunk:7] Set("SIP/bluenote-08d001f8", "FAX_RX_EMAIL=<myemail>") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [<mynumber>@from-trunk:8] Answer("SIP/bluenote-08d001f8", "") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [<mynumber>@from-trunk:9] PlayTones("SIP/bluenote-08d001f8", "ring") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [<mynumber>@from-trunk:10] NVFaxDetect("SIP/bluenote-08d001f8", "0") in new stack
[Sep 8 09:46:39] DEBUG[3573] app_nv_faxdetect-1.0.6_1.4.c: Preparing detect of fax (waitdur=4ms, sildur=1000ms, mindur=100ms, maxdur=-1ms)
[Sep 8 09:46:39] DEBUG[3573] app_nv_faxdetect-1.0.6_1.4.c: Start of voice token!
[Sep 8 09:46:39] DEBUG[3573] app_nv_faxdetect-1.0.6_1.4.c: Found unqualified token of 0 ms
[Sep 8 09:46:39] DEBUG[3573] app_nv_faxdetect-1.0.6_1.4.c: Got hangup
[Sep 8 09:46:39] VERBOSE[3573] logger.c: == Spawn extension (from-trunk, <mynumber>, 10) exited non-zero on 'SIP/bluenote-08d001f8'
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [h@from-trunk:1] NoOp("SIP/bluenote-08d001f8", "Catch-All DID Match - Found h - You probably want a DID for this.") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [h@from-trunk:2] Goto("SIP/bluenote-08d001f8", "ext-did|s|1") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Goto (ext-did,s,1)
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [s@ext-did:1] Set("SIP/bluenote-08d001f8", "__FROM_DID=s") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [s@ext-did:2] Gosub("SIP/bluenote-08d001f8", "app-blacklist-check|s|1") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [s@app-blacklist-check:1] LookupBlacklist("SIP/bluenote-08d001f8", "") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [s@app-blacklist-check:2] GotoIf("SIP/bluenote-08d001f8", "0?blacklisted") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [s@app-blacklist-check:3] Return("SIP/bluenote-08d001f8", "") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [s@ext-did:3] GotoIf("SIP/bluenote-08d001f8", "1 ?cidok") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Goto (ext-did,s,5)
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [s@ext-did:5] NoOp("SIP/bluenote-08d001f8", "CallerID is "<customernumber>" <<customernumber>>") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [s@ext-did:6] Goto("SIP/bluenote-08d001f8", "timeconditions|2|1") in new stack
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Goto (timeconditions,2,1)
[Sep 8 09:46:39] VERBOSE[3573] logger.c: -- Executing [2@timeconditions:1] GotoIfTime("SIP/bluenote-08d001f8", "12:00-20:00|mon-fri|*|*?ext-group|601|1") in new stack
The call comes in, the DID is detected, then the fax detection picks up. After fax detection instead of the DID I see "h" - "Catch-All DID Match - Found h - You probably want a DID for this." The customer is then dumped into the catch-all inbound route which is not the correct result on this call.
Another code sample - different caller, same incoming DID, call again is misrouted after fax detection:
[Sep 6 09:41:00] VERBOSE[6269] logger.c: [Sep 6 09:41:00] -- Executing [<mynumber>@from-trunk:1] Set("SIP/bluenote-b7d00858", "__FROM_DID=<mynumber>") in new stack
[Sep 6 09:41:00] VERBOSE[6269] logger.c: [Sep 6 09:41:00] -- Executing [<mynumber>@from-trunk:2] Gosub("SIP/bluenote-b7d00858", "app-blacklist-check|s|1") in new stack
[Sep 6 09:41:00] VERBOSE[6269] logger.c: [Sep 6 09:41:00] -- Executing [s@app-blacklist-check:1] LookupBlacklist("SIP/bluenote-b7d00858", "") in new stack
[Sep 6 09:41:00] VERBOSE[6269] logger.c: [Sep 6 09:41:00] -- Executing [s@app-blacklist-check:2] GotoIf("SIP/bluenote-b7d00858", "0?blacklisted") in new stack
[Sep 6 09:41:00] VERBOSE[6269] logger.c: [Sep 6 09:41:00] -- Executing [s@app-blacklist-check:3] Return("SIP/bluenote-b7d00858", "") in new stack
[Sep 6 09:41:00] VERBOSE[6269] logger.c: [Sep 6 09:41:00] -- Executing [<mynumber>@from-trunk:3] GotoIf("SIP/bluenote-b7d00858", "1 ?cidok") in new stack
[Sep 6 09:41:00] VERBOSE[6269] logger.c: [Sep 6 09:41:00] -- Goto (from-trunk,<mynumber>,5)
[Sep 6 09:41:00] VERBOSE[6269] logger.c: [Sep 6 09:41:00] -- Executing [<mynumber>@from-trunk:5] NoOp("SIP/bluenote-b7d00858", "CallerID is "<customernumber>" <<customernumber>>") in n$
[Sep 6 09:41:00] VERBOSE[6269] logger.c: [Sep 6 09:41:00] -- Executing [<mynumber>@from-trunk:6] Set("SIP/bluenote-b7d00858", "FAX_RX_EMAIL=<myemail>") in new s$
[Sep 6 09:41:00] VERBOSE[6269] logger.c: [Sep 6 09:41:00] -- Executing [<mynumber>@from-trunk:7] Answer("SIP/bluenote-b7d00858", "") in new stack
[Sep 6 09:41:00] VERBOSE[6269] logger.c: [Sep 6 09:41:00] -- Executing [<mynumber>@from-trunk:8] PlayTones("SIP/bluenote-b7d00858", "ring") in new stack
[Sep 6 09:41:00] VERBOSE[6269] logger.c: [Sep 6 09:41:00] -- Executing [<mynumber>@from-trunk:9] NVFaxDetect("SIP/bluenote-b7d00858", "0") in new stack
[Sep 6 09:41:00] DEBUG[6269] app_nv_faxdetect-1.0.6_1.4.c: Preparing detect of fax (waitdur=4ms, sildur=1000ms, mindur=100ms, maxdur=-1ms)
[Sep 6 09:41:00] DEBUG[6269] app_nv_faxdetect-1.0.6_1.4.c: Start of voice token!
[Sep 6 09:41:01] DEBUG[6269] app_nv_faxdetect-1.0.6_1.4.c: Found unqualified token of 0 ms
[Sep 6 09:41:02] DEBUG[6269] app_nv_faxdetect-1.0.6_1.4.c: Start of voice token!
[Sep 6 09:41:04] DEBUG[6269] app_nv_faxdetect-1.0.6_1.4.c: Found qualified token of 380 ms
[Sep 6 09:41:04] NOTICE[6269] app_nv_faxdetect-1.0.6_1.4.c: Redirecting SIP/bluenote-b7d00858 to talk extension
[Sep 6 09:41:04] VERBOSE[6269] logger.c: [Sep 6 09:41:04] -- Executing [talk@from-trunk:1] NoOp("SIP/bluenote-b7d00858", "Catch-All DID Match - Found talk - You probably wa$
[Sep 6 09:41:04] VERBOSE[6269] logger.c: [Sep 6 09:41:04] -- Executing [talk@from-trunk:2] Goto("SIP/bluenote-b7d00858", "ext-did|s|1") in new stack
[Sep 6 09:41:04] VERBOSE[6269] logger.c: [Sep 6 09:41:04] -- Goto (ext-did,s,1)
[Sep 6 09:41:04] VERBOSE[6269] logger.c: [Sep 6 09:41:04] -- Executing [s@ext-did:1] Set("SIP/bluenote-b7d00858", "__FROM_DID=s") in new stack
[Sep 6 09:41:04] VERBOSE[6269] logger.c: [Sep 6 09:41:04] -- Executing [s@ext-did:2] Gosub("SIP/bluenote-b7d00858", "app-blacklist-check|s|1") in new stack
[Sep 6 09:41:04] VERBOSE[6269] logger.c: [Sep 6 09:41:04] -- Executing [s@app-blacklist-check:1] LookupBlacklist("SIP/bluenote-b7d00858", "") in new stack
[Sep 6 09:41:04] VERBOSE[6269] logger.c: [Sep 6 09:41:04] -- Executing [s@app-blacklist-check:2] GotoIf("SIP/bluenote-b7d00858", "0?blacklisted") in new stack
[Sep 6 09:41:04] VERBOSE[6269] logger.c: [Sep 6 09:41:04] -- Executing [s@app-blacklist-check:3] Return("SIP/bluenote-b7d00858", "") in new stack
[Sep 6 09:41:04] VERBOSE[6269] logger.c: [Sep 6 09:41:04] -- Executing [s@ext-did:3] GotoIf("SIP/bluenote-b7d00858", "1 ?cidok") in new stack
[Sep 6 09:41:04] VERBOSE[6269] logger.c: [Sep 6 09:41:04] -- Goto (ext-did,s,5)
"Catch-All DID Match - Found talk" - that's no good. Again this call is dumped into the catch-all which is again not the right answer.
I can't duplicate this by calling in myself. I've tried my cell, my home and another phone in the office. None can re-create the problem, but I have had at least 3 customers in the last week get mis-routed in this way. Hopefully disabling fax detection will fix the short-term problem but I can't test until one of those problem customers calls back. Even then I won't know for sure - it doesn't happen all the time with those customers.
Server info:
[trixbox1.localdomain asterisk]# asterisk -V Asterisk 1.4.20-1 RPM by <a href="mailto:vc-rpms@voipconsulting.nl">vc-rpms@voipconsulting.nl</a> [trixbox1.localdomain asterisk]# uname -a Linux trixbox1.localdomain 2.6.18-53.1.4.el5 #1 SMP Fri Nov 30 00:45:16 EST 2007 i686 i686 i386 GNU/Linux [trixbox1.localdomain asterisk]#
TrixBox 2.6.1, installed from CD some weeks ago.
The box is a Dell P4. The trunks that have this problem are all SIP trunks, my POTS line doesn't have the same issue....but I have fax detection turned off on that line.
I'm OK with just turning off fax detection (not sure why I turned it on in the first place) but this could be a bigger problem. Any ideas?
 
Member Since:
2006-12-23