Solved SIP Message Exchange in a 3CX-App / Trunk to PSTN Setup (Req. Reference)

Status
Not open for further replies.

Toby&Dave

New User
Joined
Jul 26, 2021
Messages
2
Reaction score
2
Hi folks

First of all thanks to the team for this software. The admin webgui is clean and things are straight forward to configure and everything feels pretty fast and responsive compared to other solutions (config changes are applied almost immediately and even service restarts are pretty fast. It's fun playing around with the 3CX solution).


Part I / II

Keywords:
CUBE, Mobile, App, Trunk, SIP, INVITE, SBC, 3CX Tunnel, Cisco, B2BUA

Who can help us:
a) People that have set up a predefined or general SIP trunk and can successfully make calls to the PSTN from the 3CX Mobile App -> You could help us with a trace / by posting the exchanged SIP Messages measured a) on the Mobile device itself and b) On the 3CX PBX (Admin GUI > Dashboard > Activity Log)

b) 3CX Devs/Engineers that could shed some light on how the 3CX PBX processes incoming SIP messages. We're especially interested in which criteria are used to validate incoming SIP messages (as we see "Malformed SIP request received" in the Admin GUI > Dashboard > Activity Log, but can't quite figure out what exactly the 3CX PBX doesn't like about some of them. Check section "What we are seeing" below for detailed information)



What would really help
A reference guide for this particular architecture that shows the expected, ideal SIP messages exchanged between all the involved components to successfully set up a call.
Such a reference would help us craft the SIP messages on the SBC (Cisco CUBE) into the desired format.

(If somebody that got this setup working posts an anonymized trace we can reverse engineer what the SIP messages along the path should ideally look like. Such a trace would ideally also contain the SDP)


Here are some examples of what I mean:

SIP Exchange for some scenario with a CUBE SBC (Cisco), that's Cisco's dialect:
373584.jpg



Sip exchange for a scenario with a Dialogic SBC, which talks a slightly different dialect:
CF_WG_SIP_Precondition_2_2.png


Some diagram like the second one above that demonstrates what SIP message order and format 3CX expects from an SBC would be immensely helpful.




Scope / Situation / Setup:
We're running a small PoC where we try to get local 3CX Mobile Clients (App) to make outgoing calls to an external BSC (Cisco CUBE) / the PSTN.
Generic SIP Trunk configuration from 3CX to the BSC (CUBE) is straight forward and so is the configuration of inbound and outbound rules. Device configuration is self explanatory as well and I don't think we're messing up there, but who knows.



What we expect to see:

Calls beween 3CX Mobile Users work flawlessly. (Note: Those are never routed to the BSC and stay within the scope of the 3CX System)
Calls from 3CX Mobile Users to the SBC (CUBE) / PSTN work flawlessly. (Note: Those are sent over a SIP trunk to the BSC)



What we see:
Calls between 3CX Mobile App users work flawlessly.
Calls from 3CX Mobile Users to the SBC (CUBE) / PSTN do go through and it rings on the far end, but a connection can't be established. For some reason the 3CX PBX seems to discard some of the received SIP messages (In particular the 183 Session Progress message) and not pass them on to the 3CX Mobile app. What is really puzzling though is that some of the SIP messages are passed on to the 3CX Mobile App (the 100 Trying message is passed on to the 3CX Mobile App). Result of this behaviour being an incomplete SIP message exchange and funky behaviour on both ends of the call (Infinite ringing on both ends / no call tear down when one of the users terminates the call).

I've tried to sketch out what we've figured out with reverse engineering so far. If we got things wrong, please feel free to lecture us about the correct design.

3CX Mobile App to Cisco Unified Border Element CUBE SIP Messages.jpg

Here is SIP message (5) and (6) that the 3CX PBX still passes over to the 3CX SBC/to the mobile device:

SBC (Internal): 10.9.8.7
3CX PBX: 10.200.200.200


mm/dd/yyy h:mm:ss - Malformed SIP request received:
BadSip Recv 100/INVITE from 10.9.8.7:5060 tid=7b19e835ba4aaf46 Call-ID=pdy5V5ddiMynjZ1z_b0c8Q..:
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 10.200.200.200:5060;branch=z9hG4bK-524287-1---7b19e835ba4aaf46;rport=5060
To: <sip:[email protected];transport=TCP>
From: "5555"<sip:[email protected];transport=TCP>;tag=2c31ab73
Call-ID: pdy5V5ddiMynjZ1z_b0c8Q..
CSeq: 1 INVITE
Date:
Server: Cisco-SIPGateway/IOS-15.5.3.M7
Allow-Events: telephone-event
Content-Length: 0

We can find the SIP message above in the 3CX Mobile Apps logs as well, so for some reason this malformed SIP request makes it all the way from the SBC (Internal) to the 3CX App.

Then something must happen or must have happened within the 3CX PBX. It might crashed due to the malformed SIP request (notice that in the above message the SDP is missing, which might be the actual root cause for the troubles in this case - unfortunately the logs don't clearly state why the message is considered malformed), it might flushed the Call-ID of that particular call because it thought the SIP message is considered corrupt, it might just have disliked the next SIP message because it was considered "too broken to be forwarded" - we really don't know what is happening.

It seems like the 3CX PBX internally tears the call down without sending out the corresponding SIP messages but we honestly can't quite figure out what is happening inside the 3CX core components after that initial 100 Invite message made its way through to the mobile device.



The next SIP message (7) that's sent towards the 3CX Mobile App then never makes it to the mobile device (Traffic in the 3CX tunnel is encrypted and we don't know what's going on in there. Wireshark allows you to sniff on the loopback interface of the 3CX server though - that way we were able to see which SIP messages are passed on to the 3CX SBC as it uses a different port number). We still see the message arriving at the 3CX PBX but now it doesn't seem to get passed to the 3CX SBC anymore.

SBC (Internal): 10.9.8.7
3CX PBX: 10.200.200.200


mm/dd/yyy h:mm:ss - Malformed SIP request received:
BadSip Recv 183/INVITE from 10.9.8.7:5060 tid=7b19e835ba4aaf46 Call-ID=pdy5V5ddiMynjZ1z_b0c8Q..:
SIP/2.0 183 Session Progress
Via: SIP/2.0/TCP 10.200.200.200:5060;branch=z9hG4bK-524287-1---7b19e835ba4aaf46;rport=5060
Contact: <sip:[email protected]:5060;transport=tcp>
To: <sip:[email protected];transport=TCP>;tag=D5CC5D6C-B8E
From: "5555"<sip:[email protected];transport=TCP>;tag=2c31ab73
Call-ID: pdy5V5ddiMynjZ1z_b0c8Q..
CSeq: 1 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Date:
Server: Cisco-SIPGateway/IOS-15.5.3.M7
Allow-Events: telephone-event
Content-Length: 0

We guess the 3CX PBS doesn't exactly like the format of the incoming SIP message but we couldn't find any reference what the ideal, incoming SIP messages should look like to make the 3CX PBX happy.


​

 
Calls between 3CX Mobile App users work flawlessly.
Calls from 3CX Mobile Users to the SBC (CUBE) / PSTN do go through and it rings on the far end, but a connection can't be established.

Hi Dave,

I've reduced the post to the bare essentials this is the only part you should focus on - no rabbit holes ;)

Please avoid asking users to send captures or logs, I've removed that post.


SBC (Internal): 10.9.8.7
3CX PBX: 10.200.200.200


mm/dd/yyy h:mm:ss - Malformed SIP request received:
BadSip Recv 100/INVITE from 10.9.8.7:5060 tid=7b19e835ba4aaf46 Call-ID=pdy5V5ddiMynjZ1z_b0c8Q..:
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 10.200.200.200:5060;branch=z9hG4bK-524287-1---7b19e835ba4aaf46;rport=5060
To: <sip:[email protected];transport=TCP>
From: "5555"<sip:[email protected];transport=TCP>;tag=2c31ab73
Call-ID: pdy5V5ddiMynjZ1z_b0c8Q..
CSeq: 1 INVITE
Date:
Server: Cisco-SIPGateway/IOS-15.5.3.M7
Allow-Events: telephone-event
Content-Length: 0

So, on point, you got a message about a malformed request over your trunk, this is what you need to look into and nothing else. Sharp focus on this part - don't waste time troubleshooting anything beyond that - once this is fixed the calls should work.

Note our system was not designed to bridge with other systems, but rather to connect to provider trunks. It follows standard SIP message form, so if it got a malformed message then it might not reply back again.
 
Hi John,

Have to admit that I got a bit frustrated by your reply but then proceeded to go down the rabbit hole anyway thanks to your hint on what we should focus on.
We're aware that generic SIP trunks are not supportend and we don't want to waste your time on fiddling around wiht them.



Unfortunately the Malformed SIP request received error message in 3CX Activity Log is a very generic error description that doesn't give many clues about what in particular the 3CX System didn't like about the received SIP message.
The RFCs don't sharply specify every single aspect of a SIP message exchange either thus leave some room for interpretation by the developers which leads to the various flavours of SIP that all comply to the standard.


As mentioned in the deleted message either a SIP ladder diagram such as the two examples posted in the intitial message or a SIP dialogue that the 3CX PBX considers a valid message exchange as a reference for implementation would help external engineers immensely to get a 3CX PBX to talk to basically "any" SBC out there in no time without wasting hours and hours on troubleshooting things that could be tackled in no time if only the logs would be a tiny bit more specific or a reference guide with some valid SIP message exchanges as example would be available.


As for the "Malformed SIP request received" error message;
The system could point out the exact line where the validation process stumbled while processing the incoming SIP message. This would already be incredibly useful to narrow down the scope or attribute to focus on.

Anyway, we've got it working.

​

The solution for this particular case (Down the rabbit hole we go...)​

We decided to work our way through the SIP message from top to bottom.

SBC (Internal): 10.9.8.7
3CX PBX: 10.200.200.200


mm/dd/yyy h:mm:ss - Malformed SIP request received:
BadSip Recv 100/INVITE from 10.9.8.7:5060 tid=7b19e835ba4aaf46 Call-ID=pdy5V5ddiMynjZ1z_b0c8Q..:
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 10.200.200.200:5060;branch=z9hG4bK-524287-1---7b19e835ba4aaf46;rport=5060
To: <sip:[email protected];transport=TCP>
From: "5555"<sip:[email protected];transport=TCP>;tag=2c31ab73
Call-ID: pdy5V5ddiMynjZ1z_b0c8Q..
CSeq: 1 INVITE
Date:
Server: Cisco-SIPGateway/IOS-15.5.3.M7
Allow-Events: telephone-event
Content-Length: 0

Since 3CX doesn't really tell what it dislikes about the SIP messages our initial thought was that there might be some problem with the order of the attributes in the SIP message above.

Some meters down the rabbit hole we discover that the order of attributes is of no relevance according to the RFC, so it can't be that. Exception: the order of the VIA headers should not be modified.

The relative order of [SIP] header fields with different field names is not significant.

Source:
https://datatracker.ietf.org/doc/html/rfc3261#section-7.3.1


Next we checked the
rport=5060

Attribute, which our other PBX in the lab doesn't attach to SIP messages that it sends out to the ISP. We couldn't find any issues with it either.

Next thing we checked was whether there is something wrong with the To:/From: attributes. In this case the incoming messages are not in E.164 format so we thought that might be an issue. We messed around with that and made a whole lot of test calls but no luck.

To: <sip:[email protected];transport=TCP>
From: "5555"<sip:[email protected];transport=TCP>;tag=2c31ab73

Next we checked the Call-ID. Our other PBX system sends SIP messages in the format [randomID]@[IP-Address] so we thought there might be something wrong with the Call-ID. As you can see in the example below the @[IP-Address] part is entirely missing and there are only two ".." attached to the end of the string... almost looks as if some kind of search & replace function went wrong and only two dots got inserted instead of a hostname or IP.

We thought that this might be a hot lead.

However: https://datatracker.ietf.org/doc/html/rfc3261#section-20.8

According to the RFC no specific format for the Call-ID is defined, as long as it "uniquely identifies a particular invitation or all registrations of a particular client" we're good. The RFC states that "Implementations MAY use the form "localid@host"." but it's not mandatory, so basically it's up to the developers how exactly they want to format or define their Call-ID's. As long as they are unique and used in all messages within a dialog we're fine.

Call-ID: pdy5V5ddiMynjZ1z_b0c8Q..

We proceeded to check the next line but didn't discover anything interesting either.
CSeq: 1 INVITE


Then, way deep down the rabbit hole we arrived at this particular line:

The RFC https://datatracker.ietf.org/doc/html/rfc3261#section-20.17 clearly states that "SIP restricts the time zone in SIP-date to "GMT"" and also defines the format. The RFC however does not specify what happens if the Date-Attribute gets assigned with a NULL value, as it is the case in this particular message. Room for interpretation and creativity by the developers.

And this is where things get funky. In our case Cisco Call Manager (CUCM) doesn't mind that the date attribute has no valid timestamp. Calls get set up and teared down flawlessly, even though the SIP message could be considered invalid according to the RFC.

The 3CX PBX however dislikes this NULL value in the Date attribute and makes something weird and funky out of it.



Fix:
The SBC shouldn't send a SIP message without a valid date in the first place. Upon inspection we noticed that the SBC (Cisco CUBE) actually never sends a valid timestamp in any of the SIP messages it sends and receives and we started to scratch our head again.

The above SIP message gives us another valuable piece of information.

Server: Cisco-SIPGateway/IOS-15.5.3.M7

In the lab we run a bit of an older software image on our CUBE. We do not recommend to run it in production.

After a bit of digging we discovered this bug:
https://bst.cloudapps.cisco.com/bugsearch/bug/cscvf07153


In our case the suggested workaround did the job and once it was applied, the correct timestamps were included in the SIP messages and surprise surprise, suddenly all calls from 3CX Mobile Apps flawlessly went through to the PSTN.

Workaround 1: Set the router's clock as GMT.

!
no clock timezone EDT
clock timezone GMT
!




tl;dr:
The SBC didn't send a valid timestamp in the Date: header due to a bug, which caused weird behaviour in the 3CX PBX. Once the SBC sent a valid timestamp calls went through with no problem.

We've chosen to write this lenghty post to give the team a slight glimpse of how much hassle people in the field out there sometimes go through due to the very generic (read: not very helpful) error message in the activity log. And to give other people out there a hand in troubleshooting their issues.

Also shame on @Cisco for this bug, even though this particular one is fixed by now.


Best regards,
Dave
 
Last edited:
Hi Dave!

Thank you for sharing the whole thought process and finally, the solution you found, I am sure there will be people very interested in your findings!

Regarding the error message and it's verbosity, while I do understand where you're coming from as I've been down that road many times myself while doing interop work with now supported providers, this is one of the reasons we recommend using supported SIP Trunk providers (we've done this for you!).

Anyhow, I do admire your persistence and having to go through the RFCs and I'm glad to hear that everything is working now as you want it.

As there was a solution, I will flag this thread as "resolved".
 
Status
Not open for further replies.

Latest Posts

Forum statistics

Threads
112,324
Messages
591,897
Members
165,475
Latest member
lastshadow