If anyone is interested in helping create a new site logo please email webmaster@allworxforums.com

PLEASE NOTE: Allworxforums.com is not owned, nor run by Allworx Corp. The views and opinions found on this forum are not necessarily the views of Allworx or the forum moderators. Neither Allworx nor the forum will be held liable for any information found on the forum. The Allworx logo and name is a registered trademark of Allworx Corp.

6x inbound okay, outbound "400 Bad Request"

General installation and configuration help.
mcbsys
Posts: 23
Joined: Thu Apr 28, 2022 7:08 pm

6x inbound okay, outbound "400 Bad Request"

Post by mcbsys »

Hi,

I'm back with a new problem on the 6x described in this thread:
https://www.allworxforums.com/viewtopic.php?f=6&t=2838

Still on 7.4.19.2. Old, I know, but working fine until this week!

I migrated this customer from POTS to a SIP Proxy (Telnyx) connected by IP (not registration) and it's been working great for several months. This week I restarted the network stack (router, switches, Allworx) to fix an unrelated issue. After that, the Allworx can receive calls perfectly, but outbound calls terminate with "Check Number" on the phone and "400 Bad Request" in the Diagnostic Log. The call never reaches Telnyx, even though sip.telynyx.com is pingable from the Allworx. Rebooting the server and phones doesn't help.

The Allworx is in NAT/Firewall mode, LAN IP for the phones and a WAN IP on a different internal network, which then gets to the Internet through a router with appropriate ports open.

What could be behind this? Would restoring an OfficeSafe backup help?

Thanks,

Mark
wshrader
Posts: 196
Joined: Mon Apr 15, 2019 3:07 pm

Re: 6x inbound okay, outbound "400 Bad Request"

Post by wshrader »

It seems the 'unrelated issue' is related. Was the Allworx ever rebooted during this period of several months? You could try to restore a backup. The date of the backup may matter in relation to any other changes that were made but if it works then maybe some change was made to the Allworx configuration which broke it. On such an old version as v7.4, I think there were many more settings that required a reboot to effect. Something may have been changed that only took effect when you rebooted thereby breaking it. If the restore does not restore :lol: outbound calling then whatever happened with this 'unrelated issue' needs more scrutiny.

On the other hand, check your Dial Plan and SIP Proxy settings. Also check the number you're dialing. The 400 Bad Request is a response from Telnyx. Either the Allworx is actually sending bad information or the number dialed is bogus. You could contact Telnyx for more information on why they are responding with that message. They ought to be able to tell you what they received as the dialed number so you can compare it to what you really dialed. This would lead you back to the Allworx Dial Plan and Proxy settings.
I can't be strong enough in recommending you update/upgrade this server. Problems like this could either be avoided entirely or much easier to troubleshoot on a current system version. I've been supporting Allworx since 2015 and then the current version was v7.7. It is now v9.1.5.6. Trying to troubleshoot versions even older than that is like trying to fix problems with Windows XP versus Windows 10.
mcbsys
Posts: 23
Joined: Thu Apr 28, 2022 7:08 pm

Re: 6x inbound okay, outbound "400 Bad Request"

Post by mcbsys »

Thanks for your help.

The unrelated issue was slow Internet, so first I rebooted the router, but the Cisco switch disconnects when the router reboots, so I decided to just reboot the whole stack including the Allworx.

I'm double-checking with Telnyx support, but their debug logs show zero outbound attempts. Even the Allworx CDR shows no outbound calls. So I think the 400 Bad Request is internal to the Allworx, before the call is forwarded to Telnyx.

You may be onto something about a deferred reboot breaking something. I don't see a reboot in the system logs between 8/25 (as far back as it goes) and this week. Not seeing any issues in the dial plan or SIP settings, though I guess now that the CO lines are gone, I can remove them entirely.

Another thought is to try a different router. I don't fully trust their old ZyXel, though I did finally figure out how to do the port forwards.

I agree, working with old products--and a product I'm not that familiar with--is painful. I kept hoping to keep them going until we could do a nice transition to a new system (for PBX, router, switch, and computers), but that plan keeps getting pushed back due to budget.
mcbsys
Posts: 23
Joined: Thu Apr 28, 2022 7:08 pm

Re: 6x inbound okay, outbound "400 Bad Request"

Post by mcbsys »

Here the full diagnostic log on a failing call:

Code: Select all

(seqNum[362] -  7:11/18/2022 03:39:16pm) tWebThread03: SIP: Start capture all SIP messages
(seqNum[363] -  7:11/18/2022 03:39:16pm) tWebThread03: Start Logging diagnostic messages to a file.
(seqNum[364] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: === RCVD 192.168.2.101:5060 [692 bytes] ===
(seqNum[365] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: INVITE sip:916191112222@192.168.2.190:5060 SIP/2.0
(seqNum[366] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: Via: SIP/2.0/UDP 192.168.2.101:5060;branch=z9hG4bK0914879713
(seqNum[367] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: Max-Forwards: 70
(seqNum[368] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: From: "Jim" <sip:5101@192.168.2.101:5060>;tag=09148797-12
(seqNum[369] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: To: <sip:916191112222@192.168.2.190:5060>
(seqNum[370] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: Call-ID: 09148797-11@192.168.2.101
(seqNum[371] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: CSeq: 1001 INVITE
(seqNum[372] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: Supported: replaces,100rel
(seqNum[373] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: Contact: <sip:5101@192.168.2.101:5060>
(seqNum[374] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: User-Agent: IST-OP-2.4.9.4
(seqNum[375] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: Content-Type: application/sdp
(seqNum[376] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: Content-Length: 245
(seqNum[377] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: 
(seqNum[378] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: v=0
(seqNum[379] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: o=- 0 3 IN IP4 192.168.2.101
(seqNum[380] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: s=Call
(seqNum[381] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: c=IN IP4 192.168.2.101
(seqNum[382] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: t=0 0
(seqNum[383] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: m=audio 16384 RTP/AVP 0 18 96
(seqNum[384] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: a=ptime:20
(seqNum[385] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: a=rtpmap:0 PCMU/8000
(seqNum[386] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: a=rtpmap:18 G729/8000
(seqNum[387] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: a=fmtp:18 annexb=no
(seqNum[388] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: a=rtpmap:96 telephone-event/8000
(seqNum[389] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: a=fmtp:96 0-16
(seqNum[390] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: a=sendrecv
(seqNum[391] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: ===========================
(seqNum[392] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: === SENT 192.168.2.101:5060 [350 bytes] ===
(seqNum[393] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: SIP/2.0 100 Trying
(seqNum[394] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: Via: SIP/2.0/UDP 192.168.2.101:5060;branch=z9hG4bK0914879713
(seqNum[395] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: To: <sip:916191112222@192.168.2.190:5060>;tag=30d6b-17ae-10f
(seqNum[396] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: From: "Jim" <sip:5101@192.168.2.101:5060>;tag=09148797-12
(seqNum[397] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: CSeq: 1001 INVITE
(seqNum[398] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: Call-ID: 09148797-11@192.168.2.101
(seqNum[399] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: Date: Fri, 18 Nov 2022 23:39:26 GMT
(seqNum[400] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: Server: IST-OIS-7.4.19.2
(seqNum[401] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: Content-Length: 0
(seqNum[402] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: 
(seqNum[403] -  7:11/18/2022 03:39:26pm) tSip: SIP_CAPTURE: ===========================
(seqNum[404] -  7:11/18/2022 03:39:26pm) tSip: CCB_CAPTURE: CCB_INVITE: legID=275-276 lang=0 bRecRte=0 pCaller="Jim" <sip:5101@192.168.2.101:5060> streamID=272, referLegID=0-0, pUrl=sip:916191112222@192.168.2.190:5060 pReferBy=(null)
(seqNum[405] -  7:11/18/2022 03:39:26pm) tProxy: CCB_CAPTURE: CCB_INVITE: legID=277-278 lang=1 bRecRte=0 pCaller="Jim" <sip:j@192.168.2.101:5060>;ext=11112;phone=5101;vcom=0;pt=256 streamID=272, referLegID=276-275, pUrl=<sip:customerSIP47999@sip.telnyx.com:5060>;isub=2;fwd=invite;phone=5900;dial=16191112222;vcom=0;pt=32;dnisname=Telnyx via IP (without Registration) pReferBy=(null)
(seqNum[406] -  7:11/18/2022 03:39:26pm) tSip: +++ IEC [7.4.19.2:sipNet.c,586]
(seqNum[407] -  7:11/18/2022 03:39:26pm) tSip: +++ IEC [7.4.19.2:sipDialog.c,1968]
(seqNum[408] -  7:11/18/2022 03:39:26pm) tSip: +++ IEC [7.4.19.2:sipInvite.c,3527]
(seqNum[409] -  7:11/18/2022 03:39:26pm) tSip: CCB_CAPTURE: CCB_ERROR: legID=278-277 errType=0 bTerminate=0
(seqNum[410] -  7:11/18/2022 03:39:26pm) tProxy: CCB_CAPTURE: CCB_INVITE: legID=279-280 lang=1 bRecRte=0 pCaller="Jim" <sip:j@192.168.2.101:5060>;ext=11112;phone=5101;vcom=0;pt=256 streamID=272, referLegID=276-275, pUrl=<tel:5000@192.168.2.190:01>;isub=2;fwd=noanswer;phone=5000;dial=16191112222;vcom=0;pt=8;dnisname=BA 619-222-3333 pReferBy=(null)
(seqNum[411] -  7:11/18/2022 03:39:30pm) tAtt00: CCB_CAPTURE: CCB_ERROR: legID=280-279 errType=0 bTerminate=0
(seqNum[412] -  7:11/18/2022 03:39:30pm) tProxy: CCB_CAPTURE: CCB_INVITE: legID=287-288 lang=1 bRecRte=0 pCaller="Jim" <sip:j@192.168.2.101:5060>;ext=11112;phone=5101;vcom=0;pt=256 streamID=272, referLegID=276-275, pUrl=<tel:5001@192.168.2.190:02>;isub=2;fwd=noanswer;phone=5001;dial=16191112222;vcom=0;pt=8;dnisname=BA 619-222-3334 pReferBy=(null)
(seqNum[413] -  7:11/18/2022 03:39:34pm) tAtt01: CCB_CAPTURE: CCB_ERROR: legID=288-287 errType=0 bTerminate=0
(seqNum[414] -  7:11/18/2022 03:39:34pm) tProxy: CCB_CAPTURE: CCB_INVITE: legID=295-296 lang=1 bRecRte=0 pCaller="Jim" <sip:j@192.168.2.101:5060>;ext=11112;phone=5101;vcom=0;pt=256 streamID=272, referLegID=276-275, pUrl=<tel:5002@192.168.2.190:03>;isub=2;fwd=noanswer;phone=5002;dial=16191112222;vcom=0;pt=8;dnisname=BA 619-222-3335 pReferBy=(null)
(seqNum[415] -  7:11/18/2022 03:39:38pm) tAtt02: CCB_CAPTURE: CCB_ERROR: legID=296-295 errType=0 bTerminate=0
(seqNum[416] -  7:11/18/2022 03:39:38pm) tProxy: CCB_CAPTURE: CCB_ERROR: legID=276-275 errType=0 bTerminate=0
(seqNum[417] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: === SENT 192.168.2.101:5060 [403 bytes] ===
(seqNum[418] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: SIP/2.0 400 Bad Request
(seqNum[419] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: Via: SIP/2.0/UDP 192.168.2.101:5060;branch=z9hG4bK0914879713
(seqNum[420] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: To: <sip:916191112222@192.168.2.190:5060>;tag=30d6b-17ae-10f
(seqNum[421] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: From: "Jim" <sip:5101@192.168.2.101:5060>;tag=09148797-12
(seqNum[422] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: CSeq: 1001 INVITE
(seqNum[423] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: Call-ID: 09148797-11@192.168.2.101
(seqNum[424] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: Date: Fri, 18 Nov 2022 23:39:38 GMT
(seqNum[425] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: Contact: <sip:916191112222@192.168.2.190:5060>
(seqNum[426] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: Server: IST-OIS-7.4.19.2
(seqNum[427] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: Content-Length: 0
(seqNum[428] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: 
(seqNum[429] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: ===========================
(seqNum[430] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: === RCVD 192.168.2.101:5060 [399 bytes] ===
(seqNum[431] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: ACK sip:916191112222@192.168.2.190:5060 SIP/2.0
(seqNum[432] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: Via: SIP/2.0/UDP 192.168.2.101:5060;branch=z9hG4bK0914879713
(seqNum[433] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: Max-Forwards: 70
(seqNum[434] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: From: "Jim" <sip:5101@192.168.2.101:5060>;tag=09148797-12
(seqNum[435] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: To: <sip:916191112222@192.168.2.190:5060>;tag=30d6b-17ae-10f
(seqNum[436] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: Call-ID: 09148797-11@192.168.2.101
(seqNum[437] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: CSeq: 1001 ACK
(seqNum[438] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: Contact: <sip:5101@192.168.2.101:5060>
(seqNum[439] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: User-Agent: IST-OP-2.4.9.4
(seqNum[440] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: Content-Length: 0
(seqNum[441] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: 
(seqNum[442] -  7:11/18/2022 03:39:38pm) tSip: SIP_CAPTURE: ===========================
Those three lines containing "+++" look a bit odd, no? Apparently referring to specific lines in two sip modules programmed in C. The forum is stripping out the odd BEL character before each +++ (a character to play a bell on the computer speaker).

I also have a couple packet traces captured by the Allworx. I'm quite sure I asked it to capture WAN and LAN, but I only see SIP on the LAN:

Phone to Allworx: INVITE
Allworx to phone: 100 Trying
Allworx to Phone: 400 Bad Request

No SIP traffic from Allworx to Telnyx.

Trying to set up a test system for comparison.
Last edited by mcbsys on Mon Nov 21, 2022 6:53 pm, edited 3 times in total.
mcbsys
Posts: 23
Joined: Thu Apr 28, 2022 7:08 pm

Re: 6x inbound okay, outbound "400 Bad Request"

Post by mcbsys »

Got the test system set up. Somewhat different configuration, but successfully placed a call through Flowroute. Significantly, no "+++" messages in the diag log after the second CCB_INVITE, and then lots of traffic with Flowroute. So I'm thinking "+++" indicates some kind of fault code from the C program module.

I guess the next step is to start playing with backups, see if I can replicate the problem, then go back to where it was working.
mcbsys
Posts: 23
Joined: Thu Apr 28, 2022 7:08 pm

Re: 6x inbound okay, outbound "400 Bad Request"

Post by mcbsys »

Well I've duplicated the issue on my test system. Unfortunately, the issue is still present after restoring the oldest backup available from 9/15/2022.

Any idea what those "+++" lines in the diagnostic log mean?
mcbsys
Posts: 23
Joined: Thu Apr 28, 2022 7:08 pm

Re: 6x inbound okay, outbound "400 Bad Request"

Post by mcbsys »

Finally found it, though not sure how this got messed up. Under Outside Lines > SIP Proxy, I've set up Telnyx for direct IP connection. SIP Registration required is unchecked. Allworx still requires a User ID, even though I don't think this is used by Telnyx. The User ID was the one used previously when I was trying to get it working with registration (failed because it wouldn't stay alive). Meanwhile I had temporarily re-enabled registration connections at Telnyx to allow users to call out using softphones. Finally on my test system, it sent an outbound packet to Telnyx, but Telnyx apparently saw the known user ID and sent back an authentication challenge as if it wanted to register.

Anyway, I changed the User ID to be the Telnyx "SIP Connection ID", and that solved the problem. On my test system, I also tried setting the User ID to "ABCD", and that also worked. My only guess is that I had a different User ID in there before the Allworx reboot, though a reboot shouldn't revert to an earlier User ID.
Last edited by mcbsys on Mon Nov 21, 2022 6:29 pm, edited 1 time in total.
wshrader
Posts: 196
Joined: Mon Apr 15, 2019 3:07 pm

Re: 6x inbound okay, outbound "400 Bad Request"

Post by wshrader »

Excellent work!!!!
Remembering what you changed and when while troubleshooting then reverting is difficult to do!

I don't know what the "+++" means in the debug logs. There is a LOT in there that isn't published anywhere. I've hounded Allworx support in the past to get explanations for debug messages and they are not quick to give me answers. Generally if you're not using SIP registration, you can put anything in the User ID field.

I'm just curious. Could you paste the debug log where it has the 400 Bad Gateway? I still think that must be a response from Telnyx. The 400 is a SIP/HTTP response code and it doesn't make sense that the Allworx would generate that internally. Be mindeful also that packet captures done by the Allworx are a PITA. I was told the buffer is only 3MB on the newer servers (probably a lot less on x-series) which means unless you have configured filters to capture exactly what you want you're likely to miss it. The syntax for the filters is also not published anywhere. If possible I will use a stateful firewall for packet captures for this reason.
mcbsys
Posts: 23
Joined: Thu Apr 28, 2022 7:08 pm

Re: 6x inbound okay, outbound "400 Bad Request"

Post by mcbsys »

This whole experience was wonky. I must have restored five backups and they all had the old SIP user in there, so that's how it was configured when the backup was taken. Meanwhile Telnyx support was supposed to be confirming that they were not seeing the traffic. I haven't heard back yet, but now I am suspicious that the 400 came from them after all. I wonder if somehow the connection got opened successfully back at the last change (August, I think), so it was persistent until the reboot, but during that time, I deleted the registration connection at Telnyx, so they saw that old ID and couldn't take it. But then I should have seen the failed auth request like I finally did on my test system after adding a new SIP proxy from scratch. Wonky.

> Generally if you're not using SIP registration, you can put anything in the User ID field.
Except, apparently, a SIP user that used to work but no longer does!

Yeah, probably should have done a trace at the firewall. But I was literally tracing for 30 seconds with only one active call, so I don't think space was an issue. I've expanded the <code> section above to show the full diagnostic log with the four SIP packets that the Allworx reported. I kept thinking the Allworx was rejecting it for some dial plan infringement, but the phone is pretty locked down--it's hard to dial wrong (like it stops after 7 digits if you dial an area code but no "1"). BTW the system still has three disconnected CO lines configured so that's what the three extra CCB_ERRORs are, trying to use the CO lines after Telnyx SIP proxy failed.
wshrader
Posts: 196
Joined: Mon Apr 15, 2019 3:07 pm

Re: 6x inbound okay, outbound "400 Bad Request"

Post by wshrader »

Have you ever used Wireshark? You can load the entire capture in Wireshark and view the call ladder. That should definitively show which side sent the 400 Bad Request.

You can create a Service Group which contains only the SIP Proxy and assign that Service Group in the Dial Plan. This will stop the Allworx from trying the non-existent POTS lines.
Post Reply