Closed sashasaturn closed 5 years ago
It is failing parsing to parse the SDP offered in the INVITE into the separate sdp and xml metadata parts. It should be a multipart SDP being offered, with one part having type 'application/sdp' and the other part having type 'application/rs-metadata+xml' or 'application/rs-metadata'.
You haven't shown the entire INVITE, but my guess is that the metadata part is missing or has a different content-type.
Can you show the entire drachtio log ?
drachtio_1 | 2019-01-13 19:48:35.374237 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x25c6980): events IN
drachtio_1 | 2019-01-13 19:48:35.374404 tport.c:2892 tport_recv_event() tport_recv_event(0x25c6980)
drachtio_1 | 2019-01-13 19:48:35.374487 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x25c6980) msg 0x25cc9c0 from (udp/172.32.0.2:5060) has 3395 bytes, veclen = 1
drachtio_1 | 2019-01-13 19:48:35.375628 recv 3395 bytes from udp/[X.X.X.X]:7281 at 19:48:35.374546:
drachtio_1 | INVITE sip:DOCKER_HOST:5060 SIP/2.0
drachtio_1 | Via: SIP/2.0/UDP X.X.X.X:7281;branch=z9hG4bKolqlue004gkdc9gi63j0.1
drachtio_1 | From: "Caller_Name"sip:MYPHONENUMBER@X.X.X.X:7281;user=phone;tag=1803327208-1547408915361-
drachtio_1 | To:
I think the first issue is that in the part of the multi-party body that refers to the XML, there is no whitespace between the header name and value, e,g,
--UniqueBroadWorksBoundary
Content-Type:application/rs-metadata+xml
Content-Disposition:recording-session
Content-Length:2012
I believe, per RFC 3261, there should be a space after "Content-Type:" before the value, i.e. it should be:
--UniqueBroadWorksBoundary
Content-Type: application/rs-metadata+xml
Content-Disposition: recording-session
Content-Length: 2012
It's subtle, but there is a space in the second example, missing in the first.
This is causing the parser to not be able to parse that part correctly.
Is there any chance this can be resolved on the sending side? All of the other headers in the INVITE are properly constructed except that part of the multi-part body.
A second issue we may then come to is that the xml content does not look at all like the spec for rs-metadata+xml, but maybe that's because you redacted something?
Dave,
Apologies for a delayed reply.
Unfortunately, I didn't redact any XML related tags, that's how it looks from logs. I don't think that sending side will even try to fix these problems.
Thank you very much for looking into this problem, we can close this issue.
Thanks,
Alex
Is the sending side a Broadworks server? It seems strange to me that that product would have this kind of bug, as its a fairly mature product.
We could modify the parser to accept the Content-Type: without the following space, if you wanted to try that
Sending side is Broadworks server.
If it's possible to modify the parser to accept this Content-Type without space - that would be great
Thanks in advance
Dave,
Please accept my apologies, you were right about XML, looks like I didn't copy it properly ..... sorry about that
Here is an XML part which I'm getting
--UniqueBroadWorksBoundary
Content-Type:application/rs-metadata+xml
Content-Disposition:recording-session
Content-Length:2012
<?xml version="1.0" encoding="UTF-8"?>
<recording_metadata
xmlns="urn:ietf:params:xml:ns:siprec">
<dataMode>complete</dataMode>
<recording id="urn:uuid:40e076cb-2513-4ad8-8d82-d84e76b31ab6">
<requestor>SRC</requestor>
<type>selective</type>
</recording>
<group id="urn:uuid:42ab1207-f416-477b-bd4c-23bed1a455c4" recording="urn:uuid:40e076cb-2513-4ad8-8d82-d84e76b31ab6">
<initiator>sip:CALLER_NAME</initiator>
</group>
<session id="urn:uuid:ddd71194-e649-4ed3-ab2d-fc54269c43b4" group="urn:uuid:42ab1207-f416-477b-bd4c-23bed1a455c4">
<start-time>2019-03-16T12:29:09-04:00</start-time>
</session>
<participant id="urn:uuid:14a581d6-ff14-4444-8397-348dff6f465a" session="urn:uuid:ddd71194-e649-4ed3-ab2d-fc54269c43b4">
<aor>sip:CALLER_NAME</aor>
<send>
<id>urn:uuid:2a199378-3438-445b-923f-7dd5ca3af6d1</id>
</send>
</participant>
<participant id="urn:uuid:fdd70d3f-929e-4275-beae-55a51926f6a2" session="urn:uuid:ddd71194-e649-4ed3-ab2d-fc54269c43b4">
<aor>sip:MY_EXTERNAL_NUMBER@SBC_IP;user=phone</aor>
<send>
<id>urn:uuid:2a199378-3438-445b-923f-7dd5ca3af6d1</id>
</send>
</participant>
<stream id="urn:uuid:2a199378-3438-445b-923f-7dd5ca3af6d1" session="urn:uuid:ddd71194-e649-4ed3-ab2d-fc54269c43b4">
<label>1</label>
<mode>mixed</mode>
</stream>
<extensiondata id="urn:uuid:6839a404-5029-4950-9552-8830ea2a3c35" parent="urn:uuid:ddd71194-e649-4ed3-ab2d-fc54269c43b4">
<broadWorksRecordingMetadata
xmlns="http://schema.broadsoft.com/broadworksCallRecording" version="1.0">
<extTrackingID>4528323:1</extTrackingID>
<serviceProviderID>Provider_Name</serviceProviderID>
<groupID>PROVIDER_NAME-CITY</groupID>
<userID>CALLER_NAME@DOMAIN_NAME</userID>
<callID>callhalf-13297558611:0</callID>
<callType>
<origCall>
<callingPartyNumber>sip:SBC_NUMBER@SBC_IP</callingPartyNumber>
<calledPartyNumber>sip:MY_EXTERNAL_NUMBER@SBC_IP;user=phone</calledPartyNumber>
<dialedDigits>sip:MY_EXTERNAL_NUMBER2@SBC_IP</dialedDigits>
</origCall>
</callType>
<recordingType>on</recordingType>
</broadWorksRecordingMetadata>
</extensiondata>
</recording_metadata>
SDP parts look as following
Content-Type: application/sdp
Content-Length: 300
v=0
o=BroadWorks 590000761 1 IN IP4 PUBLIC_IP
s=-
c=IN IP4 PUBLIC_IP
t=0 0
m=audio 22686 RTP/AVP 9 101 0 8 18
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendonly
a=label:1
--UniqueBroadWorksBoundary--
"
I had to work around a few problems running drachtio-siprec-recording-server with SDP and XML above
1) You are definitely right about RFC 3261, there should be a space after "Content-Type:". As soon as I "modified" opts variable before this line
return new Promise((resolve, reject) => {
in payload-parser.js it allowed me to move forward
2) I've noticed that SDP which I'm getting has a single m= (media name and transport address) entry, meanwhile few other examples of SDP in test/data/ folder in this repo have 2 media entries.
So payload-parser.js was crashing trying to regexp 2 media names from SDP
const arr = /^([^]+)(m=[^]+?)(m=[^]+?)$/.exec(sdp) ;
opts.sdp1 = `${arr[1]}${arr[2]}` ;
opts.sdp2 = `${arr[1]}${arr[3]}\r\n` ;
3) Next problem which I had was with this part of a code
const arr = /^(.*:)recording/.exec(key) ;
I think the problem was with this part in XML
<?xml version="1.0" encoding="UTF-8"?>
<recording_metadata
xmlns="urn:ietf:params:xml:ns:siprec">
workarounded "patching" opts with replacing 'recording_metadata' and 'siprec' to 'recording'
can you give me a gist with the entire SIPREC INVITE that comes in? Then I can add a test case for it and make sure to update any code necessary. I think I have already checked in a change since you created this issue, though I am unsure if it would fix your issue. If I can get the SIPREC INVITE as sent by the Broadworks, then I can create the test case and make sure the code handles it properly. (if you prefer you can send it to me directly at daveh@drachtio.org; and feel to obfuscate ip addresses etc as needed). Thanks
just checking in.....any chance of you providing that full siprec invite example so I can incorporate it into my test cases?
apologies for the delayed reply, just emailed you a gist file
Thanks for checking!
ok sorry just looking at it. Here is part of the gist that you sent me, and it does not look correct to me:
Content-Type: multipart/mixed;boundary=UniqueBroadWorksBoundary
Content-Length: 2562
MIME-Version: 1.0
--UniqueBroadWorksBoundary
Content-Type:application/rs-metadata+xml
Content-Disposition:recording-session
Content-Length:2012
<?xml version="1.0" encoding="UTF-8"?><recording_metadata xmlns="urn:ietf:params:xml:ns:siprec"><dataMode>complete</dataMode><recording id="urn:uuid:b70e4588-59a5-4562-a4f2-88b0016cc0df"><requestor>SRC</requestor><type>selective</type></recording><group id="urn:uuid:80a4b6ac-4e6f-4d8b-a2df-b94e2f4269b8" recording="urn:uuid:b70e4588-59a5-4562-a4f2-88b0016cc0df"><initiator>sip:caller_name</initiator></group><session id="urn:uuid:4c7bf504-3cc7-4b5a-b0b3-06d916581f3d" group="urn:uuid:80a4b6ac-4e6f-4d8b-a2df-b94e2f4269b8"><start-time>2019-03-28T06:51:35-04:00</start-time></session><participant id="urn:uuid:f4c925a3-fda4-40ba-997b-7f185f972079" session="urn:uuid:4c7bf504-3cc7-4b5a-b0b3-06d916581f3d"><aor>sip:caller_name</aor><send><id>urn:uuid:38dc5663-a651-4bcb-ab32-7a44d111d69e</id></send></participant><participant id="urn:uuid:8b295a8e-911b-48f0-9c79-0a923acf4fdd" session="urn:uuid:4c7bf504-3cc7-4b5a-b0b3-06d916581f3d"><aor>sip:+callee_number@SBC_IP;user=phone</aor><send><id>urn:uuid:38dc5663-a651-4bcb-ab32-7a44d111d69e</id></send></participant><stream id="urn:uuid:38dc5663-a651-4bcb-ab32-7a44d111d69e" session="urn:uuid:4c7bf504-3cc7-4b5a-b0b3-06d916581f3d"><label>1</label><mode>mixed</mode></stream><extensiondata id="urn:uuid:433049fc-d8ee-40a6-976a-08083605efaf" parent="urn:uuid:4c7bf504-3cc7-4b5a-b0b3-06d916581f3d"><broadWorksRecordingMetadata xmlns="http://schema.broadsoft.com/broadworksCallRecording" version="1.0"><extTrackingID>5192063:1</extTrackingID><serviceProviderID>PROVIDER_NAME</serviceProviderID><groupID>COMPANY_NAME</groupID><userID>caller_name@company_name.com</userID><callID>callhalf-12474956825:0</callID><callType><origCall><callingPartyNumber>sip:+1CALLER_NUMBER@SBC_IP</callingPartyNumber><calledPartyNumber>sip:+callee_number@SBC_IP;user=phone</calledPartyNumber><dialedDigits>sip:MYNUMBER@SBC_IP</dialedDigits></origCall></callType><recordingType>on</recordingType></broadWorksRecordingMetadata></extensiondata></recording_metadata>
--UniqueBroadWorksBoundary
Content-Type: application/sdp
Content-Length: 300
v=0
o=BroadWorks 680262007 1 IN IP4 CALLER_IP
s=-
c=IN IP4 CALLER_IP
t=0 0
m=audio 22956 RTP/AVP 9 8 0 18 101
a=rtpmap:0 PCMU/8000
a=rtpmap:9 G722/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendonly
a=label:1
--UniqueBroadWorksBoundary--
First of all, are there really two blank lines above the "a=sendonly", or is that a typo? That would make it an illegal sdp.
Secondly, I would expect to see two m= lines in the offer, for the two parties. Is Broadsoft mixing the two audio streams into one RTP stream or something?
Dave,
Those two empty lines in SDP is my mistake. I assume that Broadsoft is mixing RTP's into a single RTP stream, because I've never seen two m= in invite from them, but I have to check the documentation.
Dave,
We can close this case, I was able to reconfigure incoming SDP on Broаdsoft side to send two m= entries
Hi Dave,
I'm using drachtio-server + rtpengine + serverdrachtio-siprec-recording-server running in docker
Here are log messages which I'm getting:
drachtio_1 | c=IN IP4 X.X.X.X drachtio_1 | t=0 0 drachtio_1 | m=audio 22294 RTP/AVP 8 101 0 9 18 drachtio_1 | a=rtpmap:0 PCMU/8000 drachtio_1 | a=rtpmap:9 G722/8000 drachtio_1 | a=rtpmap:8 PCMA/8000 drachtio_1 | a=rtpmap:18 G729/8000 drachtio_1 | a=rtpmap:101 telephone-event/8000 siprec-server_1 | {"level":30,"time":1547408915428,"msg":"received SIPREC invite: sip:DOCKER_HOST:5060","pid":1,"hostname":"236871e294bc","callid":"BW144835361130119-1788699024@SBC_IP","v":1} drachtio_1 | a=fmtp:101 0-15 drachtio_1 | a=ptime:20 drachtio_1 | a=sendonly siprec-server_1 | {"level":50,"time":1547408915438,"msg":"Error connecting call: Error: expected multipart SIPREC body","pid":1,"hostname":"236871e294bc","callid":"BW144835361130119-1788699024@SBC_IP","v":1} drachtio_1 | a=label:1 drachtio_1 | drachtio_1 | --UniqueBroadWorksBoundary-- drachtio_1 | 2019-01-13 19:48:35.375710 tport.c:3051 tport_deliver() tport_deliver(0x25c6980): msg 0x25cc9c0 (3395 bytes) from udp/X.X.X.X:5060 next=(nil) drachtio_1 | 2019-01-13 19:48:35.375803 nta.c:2968 agent_recv_request() nta: received INVITE sip:DOCKER_HOST:5060 SIP/2.0 (CSeq 610344401) drachtio_1 | 2019-01-13 19:48:35.375882 nta.c:3183 agent_recv_request() nta: INVITE (610344401) to message callback drachtio_1 | 2019-01-13 19:48:35.375928 processMessageStatelessly - incoming message with call-id BW144835361130119-1788699024@SBC_IP does not match an existing call leg, processed in thread 140623077115776 drachtio_1 | 2019-01-13 19:48:35.376039 tport.c:3285 tport_tsend() tport_tsend(0x25c6980) tpn = UDP/X.X.X.X:7281 drachtio_1 | 2019-01-13 19:48:35.376098 tport.c:4085 tport_resolve() tport_resolve addrinfo = X.X.X.X:7281 drachtio_1 | 2019-01-13 19:48:35.376260 tport.c:3531 tport_send_msg() tport_vsend returned 331 drachtio_1 | 2019-01-13 19:48:35.376472 send 331 bytes to udp/[X.X.X.X]:7281 at 19:48:35.376160: drachtio_1 | SIP/2.0 100 Trying drachtio_1 | Via: SIP/2.0/UDP X.X.X.X:7281;branch=z9hG4bKolqlue004gkdc9gi63j0.1;rport=7281 drachtio_1 | From: "Caller_Name" sip:MYPHONENUMBER@X.X.X.X:7281;user=phone;tag=1803327208-1547408915361- drachtio_1 | To:
drachtio_1 | Call-ID: BW144835361130119-1788699024@SBC_IP
drachtio_1 | CSeq: 610344401 INVITE
drachtio_1 | Content-Length: 0
drachtio_1 |
drachtio_1 | 2019-01-13 19:48:35.376558 ClientController::selectClientForRequestOutsideDialog - there are 1 possible clients, we are starting with offset 0
drachtio_1 | 2019-01-13 19:48:35.376620 ClientController::route_request_outside_dialog - Selected client at offset 0
drachtio_1 | 2019-01-13 19:48:35.376732 PendingRequestController::add - tport: 0x25c6980, Call-ID: BW144835361130119-1788699024@SBC_IP, transactionId 1cd3071e-238b-42d7-9b4c-b4c4f50dbfb2
drachtio_1 | 2019-01-13 19:48:35.376789 pending-request: Adding entry to go off in 64000ms
drachtio_1 | 2019-01-13 19:48:35.376833 pending-request: Adding entry to the head (queue was empty), length: 1
drachtio_1 | 2019-01-13 19:48:35.376935 ClientController::addNetTransaction: transactionId 1cd3071e-238b-42d7-9b4c-b4c4f50dbfb2; size: 1
drachtio_1 | 2019-01-13 19:48:35.400018 Client::write_handler - wrote 3543 bytes: system:0
drachtio_1 | 2019-01-13 19:48:35.403833 No connected clients found to handle incoming cdr:attempt request
drachtio_1 | 2019-01-13 19:48:38.371276 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x25c6980): events IN
drachtio_1 | 2019-01-13 19:48:38.371444 tport.c:2892 tport_recv_event() tport_recv_event(0x25c6980)
drachtio_1 | 2019-01-13 19:48:38.371508 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x25c6980) msg 0x25cdad0 from (udp/172.32.0.2:5060) has 354 bytes, veclen = 1
drachtio_1 | 2019-01-13 19:48:38.371833 recv 354 bytes from udp/[X.X.X.X]:7281 at 19:48:38.371569:
drachtio_1 | CANCEL sip:DOCKER_HOST:5060 SIP/2.0
drachtio_1 | Via: SIP/2.0/UDP X.X.X.X:7281;branch=z9hG4bKolqlue004gkdc9gi63j0.1
drachtio_1 | CSeq: 610344401 CANCEL
drachtio_1 | From: "Caller_Name"sip:MYPHONENUMBER@X.X.X.X:7281;user=phone;tag=1803327208-1547408915361-
drachtio_1 | To:
drachtio_1 | Call-ID: BW144835361130119-1788699024@SBC_IP
drachtio_1 | Max-Forwards: 69
drachtio_1 | Content-Length: 0
drachtio_1 |
drachtio_1 | 2019-01-13 19:48:38.371895 tport.c:3051 tport_deliver() tport_deliver(0x25c6980): msg 0x25cdad0 (354 bytes) from udp/X.X.X.X:5060 next=(nil)
drachtio_1 | 2019-01-13 19:48:38.371947 nta.c:2968 agent_recv_request() nta: received CANCEL sip:DOCKER_HOST:5060 SIP/2.0 (CSeq 610344401)
drachtio_1 | 2019-01-13 19:48:38.372012 nta.c:3183 agent_recv_request() nta: CANCEL (610344401) to message callback
drachtio_1 | 2019-01-13 19:48:38.372054 processMessageStatelessly - incoming message with call-id BW144835361130119-1788699024@SBC_IP does not match an existing call leg, processed in thread 140623077115776
drachtio_1 | 2019-01-13 19:48:38.372126 received quick cancel for invite that is out to client for disposition: BW144835361130119-1788699024@SBC_IP
drachtio_1 | 2019-01-13 19:48:38.372493 Client::write_handler - wrote 500 bytes: system:0
drachtio_1 | 2019-01-13 19:48:38.372611 tport.c:3285 tport_tsend() tport_tsend(0x25c6980) tpn = UDP/X.X.X.X:7281
drachtio_1 | 2019-01-13 19:48:38.372674 tport.c:4085 tport_resolve() tport_resolve addrinfo = X.X.X.X:7281
drachtio_1 | 2019-01-13 19:48:38.372829 tport.c:3531 tport_send_msg() tport_vsend returned 345
drachtio_1 | 2019-01-13 19:48:38.373042 send 345 bytes to udp/[X.X.X.X]:7281 at 19:48:38.372732:
drachtio_1 | SIP/2.0 200 OK
drachtio_1 | Via: SIP/2.0/UDP X.X.X.X:7281;branch=z9hG4bKolqlue004gkdc9gi63j0.1;rport=7281
drachtio_1 | From: "Caller_Name" sip:MYPHONENUMBER@X.X.X.X:7281;user=phone;tag=1803327208-1547408915361-
drachtio_1 | To: ;tag=4cNNcvS2c2BXp
drachtio_1 | Call-ID: BW144835361130119-1788699024@SBC_IP
drachtio_1 | CSeq: 610344401 CANCEL
drachtio_1 | Content-Length: 0
drachtio_1 |
drachtio_1 | 2019-01-13 19:48:38.373181 tport.c:3285 tport_tsend() tport_tsend(0x25c6980) tpn = UDP/X.X.X.X:7281
drachtio_1 | 2019-01-13 19:48:38.373234 tport.c:4085 tport_resolve() tport_resolve addrinfo = X.X.X.X:7281
drachtio_1 | 2019-01-13 19:48:38.373334 tport.c:3531 tport_send_msg() tport_vsend returned 361
drachtio_1 | 2019-01-13 19:48:38.373541 send 361 bytes to udp/[X.X.X.X]:7281 at 19:48:38.373283:
drachtio_1 | SIP/2.0 487 Request Terminated
drachtio_1 | Via: SIP/2.0/UDP X.X.X.X:7281;branch=z9hG4bKolqlue004gkdc9gi63j0.1;rport=7281
drachtio_1 | From: "Caller_Name" sip:MYPHONENUMBER@X.X.X.X:7281;user=phone;tag=1803327208-1547408915361-
drachtio_1 | To: ;tag=5NeeeQa69a2Fj
drachtio_1 | Call-ID: BW144835361130119-1788699024@SBC_IP
drachtio_1 | CSeq: 610344401 INVITE
drachtio_1 | Content-Length: 0
drachtio_1 |
drachtio_1 | 2019-01-13 19:48:38.379436 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x25c6980): events IN
drachtio_1 | 2019-01-13 19:48:38.379592 tport.c:2892 tport_recv_event() tport_recv_event(0x25c6980)
drachtio_1 | 2019-01-13 19:48:38.379656 tport.c:3233 tport_recv_iovec() tport_recv_iovec(0x25c6980) msg 0x25ce310 from (udp/172.32.0.2:5060) has 366 bytes, veclen = 1
drachtio_1 | 2019-01-13 19:48:38.379979 recv 366 bytes from udp/[X.X.X.X]:7281 at 19:48:38.379714:
drachtio_1 | ACK sip:DOCKER_HOST:5060 SIP/2.0
drachtio_1 | Via: SIP/2.0/UDP X.X.X.X:7281;branch=z9hG4bKolqlue004gkdc9gi63j0.1
drachtio_1 | CSeq: 610344401 ACK
drachtio_1 | From: "Caller_Name"sip:MYPHONENUMBER@X.X.X.X:7281;user=phone;tag=1803327208-1547408915361-
drachtio_1 | To: ;tag=5NeeeQa69a2Fj
drachtio_1 | Call-ID: BW144835361130119-1788699024@SBC_IP
drachtio_1 | Max-Forwards: 69
drachtio_1 | Content-Length: 0