SIP MESSAGE event lost between Drachtio Server and Drachtio-srf

p-akshay commented 3 years ago

Scenario:

Client Registers with Drachtio Server
Client then generates a SIP MESSAGE event.
This event is visible on Drachtio Server.
However, the node application using drachtio-srf, does not receive this event and throws out the error.

Following are the relevant logs for Step 3

2020-09-11 14:51:07.799788 recv 2033 bytes from udp/[.23.33.81]:60320 at 14:51:07.799664: MESSAGE sip:network.org SIP/2.0 Via: SIP/2.0/UDP .23.33.81:60320;rport;branch=z9hG4bKPjZJW9Ti6h33WTUek9a-8mNQsED7H0bXNE Max-Forwards: 70 From: <sip:@network.org>;tag=kVYw1YjtJTg7qJ1zKmZW9kwXznrbup1c To: <sip:network.org> Call-ID: KAn.YwfCiaR-NPP6amLDOwEgm4ozbQ1q CSeq: 60134 MESSAGE ... ... ... 2020-09-11 14:51:07.799926 message truncated at 1831 2020-09-11 14:51:07.799972 nta.c:3036 agent_recv_request() nta: received MESSAGE sip:*network.org SIP/2.0 (CSeq 60134) 2020-09-11 14:51:07.800020 nta.c:3253 agent_recv_request() nta: MESSAGE (60134) to message callback 2020-09-11 14:51:07.800056 processMessageStatelessly - incoming message with call-id KAn.YwfCiaR-NPP6amLDOwEgm4ozbQ1q does not match an existing call leg, processed in thread 140493332515200

Error Logs for Step 4:

Error: unexpected message with type: undefined at DrachtioAgent._onMsg (/home//Documents/mcs//node_modules/drachtio-srf/lib/drachtio-agent.js:749:15) at WireProtocol.emit (events.js:198:13) at WireProtocol.processMessageBuffer (/home//Documents/mcs//node_modules/drachtio-srf/lib/wire-protocol.js:270:12) at WireProtocol._onData (/home//Documents/mcs//node_modules/drachtio-srf/lib/wire-protocol.js:304:14) at Socket.emit (events.js:198:13) at addChunk (_stream_readable.js:288:12) at readableAddChunk (_stream_readable.js:265:13) at Socket.Readable.push (_stream_readable.js:224:10) at TCP.onStreamRead [as onread] (internal/stream_base_commons.js:94:17)

Additional Work Done: When this error was observed repeatedly, I added few debug logs in "drachtio-agent.js" file, in the Function _onMsg(socket, msg) Basically I tried to get values of local variables, pos, msg, leader and token.

_onMsg(socket, msg) { const obj = this.mapServer.get(socket) ; const pos = msg.indexOf(CR) ; const leader = -1 === pos ? msg : msg.slice(0, pos) ; const token = leader.split('|') ; let res, sr, rawMsg ; console.log('Position = '); console.log(pos); console.log('Leader = '); console.log(leader); console.log('Token = '); console.log(token); console.log('msg = '); console.log(JSON.stringify(msg));

switch (token[1]) { ...

For the above mentioned scenario, following are the console logs : Position = -1 Leader =

Token = [ '' ] msg = ""

Notes:

I have worked with FreeSWITCH for quite a while before so, just to verify, I tried the same scenario on FS v1.10. The FS does recognize the event and responds with 202 Accepted.
SIP MESSAGE is visible on Wireshark
The SIP MESSAGE received is of MIME type
This happens with only a few clients.

davehorton commented 3 years ago

I believe the issue is that a large message sent over udp got truncated by sofia. This is configurable -- have you set the udp-mtu parameter? I suggest setting it to 4096, as described here

davehorton commented 3 years ago

Have you been able to try this?

p-akshay commented 3 years ago

Hi,

Yes... I was able to test the same today with mtu value set to 4096 and 8092 via config. However, the issue still remains as it is...

The incoming packet on the system (as far as i could understand) is around 2200 bytes... The network interface MTU is set to 1420...and on Wireshark I can see that the packet has arrived in 2 fragments (one full packet of 1392 Bytes and other having lesser size)

Based on Drachtio server logs, it seems the packet is truncated around 1800 bytes.

Not sure what could be issue here

davehorton commented 3 years ago

can you send me a full drachtio.log file with loglevel debug and sofia-loglevel 9 please

p-akshay commented 3 years ago

I will capture the necessary logs and will mail the same tomorrow.

Thanks

p-akshay commented 3 years ago

Here is the required log...

2020-09-17 14:40:16.543992 tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x55d6bfca7680): events IN 2020-09-17 14:40:16.544225 tport.c:2892 tport_recv_event() tport_recv_event(0x55d6bfca7680) 2020-09-17 14:40:16.544405 tport.c:3229 tport_recv_iovec() tport_recv_iovec(0x55d6bfca7680) msg 0x55d6bfcc0e70 from (udp/..46.7:5060) has 1079 bytes, veclen = 1 2020-09-17 14:40:16.544855 recv 1079 bytes from udp/[..33.81]:35354 at 14:40:16.544553: REGISTER sip:ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 Via: SIP/2.0/UDP ..33.81:35354;rport;branch=z9hG4bKPjWP8z.D6Ehqem9rUbMMoLEYHMglzJbQgE Max-Forwards: 70 From: sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=KJaTZjteAxXFNIOZtrb2YXBwrcAogsRx To: sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org Call-ID: kWUM4KOVzryFzxUnR6Q3rN-cy8LMVXAy CSeq: 54507 REGISTER Authorization: Digest username="mcx.test-111.mcla", realm="ims.mnc001.mcc001.3gppnetwork.org", nonce="80bb18d9-53c5-418f-897c-595dd04b7828", uri="sip:ims.mnc001.mcc001.3gppnetwork.org", response="1d145678b5e79d6ef9173b11d4be5475", algorithm=MD5, cnonce="KZQ8SjdLoFpM4tcrtUm9JlylmO1CvEa.", qop=auth, nc=00000007 P-Preferred-Identity: sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org User-Agent: TEST e-TBS Contact: sip:mcx.test-111.mcla@*.*.33.81:35354;ob;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mcptt";+g.3gpp.mcptt Expires: 300 Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Content-Length: 0

2020-09-17 14:40:16.545010 tport.c:3047 tport_deliver() tport_deliver(0x55d6bfca7680): msg 0x55d6bfcc0e70 (1079 bytes) from udp/..33.81:5060 next=(nil) 2020-09-17 14:40:16.545117 nta.c:3036 agent_recv_request() nta: received REGISTER sip:ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 (CSeq 54507) 2020-09-17 14:40:16.545214 nta.c:3253 agent_recv_request() nta: REGISTER (54507) to message callback 2020-09-17 14:40:16.545286 processMessageStatelessly - incoming message with call-id kWUM4KOVzryFzxUnR6Q3rN-cy8LMVXAy does not match an existing call leg, processed in thread 140391939795328 2020-09-17 14:40:16.545369 ClientController::selectClientForRequestOutsideDialog - there are 1 possible clients, we are starting with offset 0 2020-09-17 14:40:16.545428 ClientController::route_request_outside_dialog - Selected client at offset 0 2020-09-17 14:40:16.545509 PendingRequestController::add - tport: 0x55d6bfca7680, Call-ID: kWUM4KOVzryFzxUnR6Q3rN-cy8LMVXAy, transactionId 915671d9-849b-49a4-800f-e72cd4caccc1 2020-09-17 14:40:16.545581 pending-request: Adding entry to go off in 64000ms 2020-09-17 14:40:16.545636 pending-request: Adding entry to the head (queue was empty), length: 1 2020-09-17 14:40:16.545725 ClientController::addNetTransaction: transactionId 915671d9-849b-49a4-800f-e72cd4caccc1; size: 1 2020-09-17 14:40:16.546034 Client::write_handler - wrote 1240 bytes: system:0 2020-09-17 14:40:16.553559 Client::read_handler read: 073f478e-2786-4f0f-af20-ebc5e6cf14ae|sip|915671d9-849b-49a4-800f-e72cd4caccc1| SIP/2.0 200 OK Call-ID: kWUM4KOVzryFzxUnR6Q3rN-cy8LMVXAy cseq: 54507 REGISTER from: sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=KJaTZjteAxXFNIOZtrb2YXBwrcAogsRx to: sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org Content-Length: 0 contact: sip:mcx.test-111.mcla@..33.81:35354;ob;expires=120 user-agent: MCLabs Registration Server

2020-09-17 14:40:16.553648 Client::processMessage - got request with 4 tokens 2020-09-17 14:40:16.553669 Client::processMessage - request id 073f478e-2786-4f0f-af20-ebc5e6cf14ae, request type: sip transaction id: 915671d9-849b-49a4-800f-e72cd4caccc1, dialog id: 2020-09-17 14:40:16.553688 ClientController::addApiRequest: clientMsgId 073f478e-2786-4f0f-af20-ebc5e6cf14ae; size: 1 2020-09-17 14:40:16.553745 SipDialogController::doRespondToSipRequest thread 140391939795328 2020-09-17 14:40:16.553806 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId 915671d9-849b-49a4-800f-e72cd4caccc1 2020-09-17 14:40:16.553845 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - failed to find transactionId 915671d9-849b-49a4-800f-e72cd4caccc1, most likely this is a response to an invite we sent 2020-09-17 14:40:16.553910 pending-request: removing entry, prior to removal length: 1 2020-09-17 14:40:16.553944 pending-request: removed entry, timer not set (queue is empty after removal), length: 0 2020-09-17 14:40:16.553987 SipDialogController::addIncomingRequestTransaction - adding transactionId 915671d9-849b-49a4-800f-e72cd4caccc1 for irq:0x55d6bfcbea10 2020-09-17 14:40:16.554020 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId 915671d9-849b-49a4-800f-e72cd4caccc1 2020-09-17 14:40:16.554050 SipDialogController::doRespondToSipRequest found incoming transaction 0x55d6bfcbea10 2020-09-17 14:40:16.554081 SipTransport::getContactUri - created Contact header: sip:..46.7:5060 2020-09-17 14:40:16.554232 makeTags - Adding well-known header 'Call-ID' with value 'kWUM4KOVzryFzxUnR6Q3rN-cy8LMVXAy' 2020-09-17 14:40:16.554276 makeTags - Adding well-known header 'cseq' with value '54507 REGISTER' 2020-09-17 14:40:16.554311 makeTags - Adding well-known header 'from' with value 'sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=KJaTZjteAxXFNIOZtrb2YXBwrcAogsRx' 2020-09-17 14:40:16.554335 makeTags - Adding well-known header 'to' with value 'sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org' 2020-09-17 14:40:16.554354 makeTags - Adding well-known header 'contact' with value 'sip:mcx.test-111.mcla@..33.81:35354;ob;expires=120' 2020-09-17 14:40:16.554371 makeTags - Adding well-known header 'user-agent' with value 'MCLabs Registration Server' 2020-09-17 14:40:16.554446 tport.c:3284 tport_tsend() tport_tsend(0x55d6bfca7680) tpn = UDP/..33.81:35354 2020-09-17 14:40:16.554486 tport.c:4081 tport_resolve() tport_resolve addrinfo = ..33.81:35354 2020-09-17 14:40:16.554613 tport.c:3531 tport_send_msg() tport_vsend returned 491 2020-09-17 14:40:16.554665 send 491 bytes to udp/[..33.81]:35354 at 14:40:16.554526: SIP/2.0 200 OK Via: SIP/2.0/UDP ..33.81:35354;rport=35354;branch=z9hG4bKPjWP8z.D6Ehqem9rUbMMoLEYHMglzJbQgE From: sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=KJaTZjteAxXFNIOZtrb2YXBwrcAogsRx To: sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=50NHarrymtt7F Call-ID: kWUM4KOVzryFzxUnR6Q3rN-cy8LMVXAy CSeq: 54507 REGISTER Contact: sip:mcx.test-111.mcla@*.*.33.81:35354;ob;expires=120 User-Agent: MCLabs Registration Server Content-Length: 0

2020-09-17 14:40:16.554703 nta.c:6948 incoming_reply() nta: sent 200 OK for REGISTER (54507) 2020-09-17 14:40:16.554725 nta.c:1411 set_timeout() nta: timer set to 32000 ms 2020-09-17 14:40:16.554748 SipDialogController::doRespondToSipRequest destroying irq 0x55d6bfcbea10 2020-09-17 14:40:16.554784 ClientController::removeApiRequest: clientMsgId 073f478e-2786-4f0f-af20-ebc5e6cf14ae; size: 0 2020-09-17 14:40:16.554816 ClientController::removeNetTransaction: transactionId 915671d9-849b-49a4-800f-e72cd4caccc1; size: 0 2020-09-17 14:40:16.554884 Client::write_handler - wrote 684 bytes: system:0 2020-09-17 14:40:17.182306 tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x55d6bfca7680): events IN 2020-09-17 14:40:17.182651 tport.c:2892 tport_recv_event() tport_recv_event(0x55d6bfca7680) 2020-09-17 14:40:17.182852 tport.c:3229 tport_recv_iovec() tport_recv_iovec(0x55d6bfca7680) msg 0x55d6bfcbca00 from (udp/..46.7:5060) has 1079 bytes, veclen = 1 2020-09-17 14:40:17.183397 recv 1079 bytes from udp/[..33.83]:56416 at 14:40:17.183024: REGISTER sip:ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 Via: SIP/2.0/UDP ..33.83:56416;rport;branch=z9hG4bKPjpnQX3jQsYauYEaUdZZEWheg-ScfVjIkp Max-Forwards: 70 From: sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=W1n4SW-iwBbJI7HK0M3K5rPC9MziEf0z To: sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org Call-ID: pssmghIGEtkh01SKNlPIXh20vnzvvJYJ CSeq: 21074 REGISTER Authorization: Digest username="mcx.test-333.mcla", realm="ims.mnc001.mcc001.3gppnetwork.org", nonce="7711b6c2-a84c-4884-bb05-9f098bf675da", uri="sip:ims.mnc001.mcc001.3gppnetwork.org", response="dd770166f3f665dc5740a0a4f97295ba", algorithm=MD5, cnonce="xw7dkG-KvI43-a0tS-OusMb4OXse6G39", qop=auth, nc=00000007 P-Preferred-Identity: sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org User-Agent: TEST e-TBS Contact: sip:mcx.test-333.mcla@*.*.33.83:56416;ob;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mcptt";+g.3gpp.mcptt Expires: 300 Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Content-Length: 0

2020-09-17 14:40:17.183596 tport.c:3047 tport_deliver() tport_deliver(0x55d6bfca7680): msg 0x55d6bfcbca00 (1079 bytes) from udp/..33.83:5060 next=(nil) 2020-09-17 14:40:17.183749 nta.c:3036 agent_recv_request() nta: received REGISTER sip:ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 (CSeq 21074) 2020-09-17 14:40:17.183925 nta.c:3253 agent_recv_request() nta: REGISTER (21074) to message callback 2020-09-17 14:40:17.184063 processMessageStatelessly - incoming message with call-id pssmghIGEtkh01SKNlPIXh20vnzvvJYJ does not match an existing call leg, processed in thread 140391939795328 2020-09-17 14:40:17.184206 ClientController::selectClientForRequestOutsideDialog - there are 1 possible clients, we are starting with offset 0 2020-09-17 14:40:17.184344 ClientController::route_request_outside_dialog - Selected client at offset 0 2020-09-17 14:40:17.184523 PendingRequestController::add - tport: 0x55d6bfca7680, Call-ID: pssmghIGEtkh01SKNlPIXh20vnzvvJYJ, transactionId 9e30b2d8-4655-4225-b919-19fd791c9b21 2020-09-17 14:40:17.184655 pending-request: Adding entry to go off in 64000ms 2020-09-17 14:40:17.184805 pending-request: Adding entry to the head (queue was empty), length: 1 2020-09-17 14:40:17.184981 ClientController::addNetTransaction: transactionId 9e30b2d8-4655-4225-b919-19fd791c9b21; size: 1 2020-09-17 14:40:17.185420 Client::write_handler - wrote 1240 bytes: system:0 2020-09-17 14:40:17.205000 Client::read_handler read: 35626d8f-785f-4579-92d1-8efd906afcb3|sip|9e30b2d8-4655-4225-b919-19fd791c9b21| SIP/2.0 200 OK Call-ID: pssmghIGEtkh01SKNlPIXh20vnzvvJYJ cseq: 21074 REGISTER from: sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=W1n4SW-iwBbJI7HK0M3K5rPC9MziEf0z to: sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org Content-Length: 0 contact: sip:mcx.test-333.mcla@..33.83:56416;ob;expires=120 user-agent: MCLabs Registration Server

2020-09-17 14:40:17.205105 Client::processMessage - got request with 4 tokens 2020-09-17 14:40:17.205137 Client::processMessage - request id 35626d8f-785f-4579-92d1-8efd906afcb3, request type: sip transaction id: 9e30b2d8-4655-4225-b919-19fd791c9b21, dialog id: 2020-09-17 14:40:17.205158 ClientController::addApiRequest: clientMsgId 35626d8f-785f-4579-92d1-8efd906afcb3; size: 1 2020-09-17 14:40:17.205213 SipDialogController::doRespondToSipRequest thread 140391939795328 2020-09-17 14:40:17.205252 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId 9e30b2d8-4655-4225-b919-19fd791c9b21 2020-09-17 14:40:17.205278 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - failed to find transactionId 9e30b2d8-4655-4225-b919-19fd791c9b21, most likely this is a response to an invite we sent 2020-09-17 14:40:17.205323 pending-request: removing entry, prior to removal length: 1 2020-09-17 14:40:17.205348 pending-request: removed entry, timer not set (queue is empty after removal), length: 0 2020-09-17 14:40:17.205382 SipDialogController::addIncomingRequestTransaction - adding transactionId 9e30b2d8-4655-4225-b919-19fd791c9b21 for irq:0x55d6bfcc3350 2020-09-17 14:40:17.205409 SipDialogController::findAndRemoveTransactionIdForIncomingRequest - searching transactionId 9e30b2d8-4655-4225-b919-19fd791c9b21 2020-09-17 14:40:17.205430 SipDialogController::doRespondToSipRequest found incoming transaction 0x55d6bfcc3350 2020-09-17 14:40:17.205453 SipTransport::getContactUri - created Contact header: sip:..46.7:5060 2020-09-17 14:40:17.205541 makeTags - Adding well-known header 'Call-ID' with value 'pssmghIGEtkh01SKNlPIXh20vnzvvJYJ' 2020-09-17 14:40:17.205570 makeTags - Adding well-known header 'cseq' with value '21074 REGISTER' 2020-09-17 14:40:17.205594 makeTags - Adding well-known header 'from' with value 'sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=W1n4SW-iwBbJI7HK0M3K5rPC9MziEf0z' 2020-09-17 14:40:17.205620 makeTags - Adding well-known header 'to' with value 'sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org' 2020-09-17 14:40:17.205645 makeTags - Adding well-known header 'contact' with value 'sip:mcx.test-333.mcla@..33.83:56416;ob;expires=120' 2020-09-17 14:40:17.205669 makeTags - Adding well-known header 'user-agent' with value 'MCLabs Registration Server' 2020-09-17 14:40:17.205721 tport.c:3284 tport_tsend() tport_tsend(0x55d6bfca7680) tpn = UDP/..33.83:56416 2020-09-17 14:40:17.205755 tport.c:4081 tport_resolve() tport_resolve addrinfo = ..33.83:56416 2020-09-17 14:40:17.205899 tport.c:3531 tport_send_msg() tport_vsend returned 491 2020-09-17 14:40:17.205960 send 491 bytes to udp/[..33.83]:56416 at 14:40:17.205790: SIP/2.0 200 OK Via: SIP/2.0/UDP ..33.83:56416;rport=56416;branch=z9hG4bKPjpnQX3jQsYauYEaUdZZEWheg-ScfVjIkp From: sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=W1n4SW-iwBbJI7HK0M3K5rPC9MziEf0z To: sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=69eacK91H3gtB Call-ID: pssmghIGEtkh01SKNlPIXh20vnzvvJYJ CSeq: 21074 REGISTER Contact: sip:mcx.test-333.mcla@*.*.33.83:56416;ob;expires=120 User-Agent: MCLabs Registration Server Content-Length: 0

2020-09-17 14:40:17.206018 nta.c:6948 incoming_reply() 2020-09-17 14:40:17.206039 SipDialogController::doRes 2020-09-17 14:40:17.206069 ClientController::removeApiRequest: 2020-09-17 14:40:17.206095 ClientController::removeNetTransaction: 2020-09-17 14:40:17.206167 Client::write_handler 2020-09-17 14:40:31.374613 DrachtioController::proces 2020-09-17 14:40:31.374911 size of hash table 2020-09-17 14:40:31.375055 size of hash table 2020-09-17 14:40:31.375158 size of hash table for dialogs 2020-09-17 14:40:31.375361 number of server-side 2020-09-17 14:40:31.375559 number of client-side 2020-09-17 14:40:31.375691 number of dialogs in the hash table 2020-09-17 14:40:31.375784 number of sip messages received 2020-09-17 14:40:31.375878 number of sip messages sent 2020-09-17 14:40:31.375954 number of sip requests received 2020-09-17 14:40:31.376026 number of sip requests sent 2020-09-17 14:40:31.376102 number of bad sip messages received 2020-09-17 14:40:31.376174 number of bad sip requests received 2020-09-17 14:40:31.376227 number of bad sip requests dropped 2020-09-17 14:40:31.376278 number of bad sip reponses dropped 2020-09-17 14:40:31.376328 number of client transactions created 2020-09-17 14:40:31.376378 number of server transactions created 2020-09-17 14:40:31.376442 number of in-dialog 2020-09-17 14:40:31.376509 number of server 2020-09-17 14:40:31.376575 number of server 2020-09-17 14:40:31.376641 number of requests 2020-09-17 14:40:31.376707 number of requests 2020-09-17 14:40:31.376773 number of responses 2020-09-17 14:40:31.376839 number of successful 2020-09-17 14:40:31.376905 number of requests merged by UAS 2020-09-17 14:40:31.376970 number of SIP responses sent by stack 2020-09-17 14:40:31.377035 number of SIP requests 2020-09-17 14:40:31.377100 number of SIP responses 2020-09-17 14:40:31.377167 number of retransmitted 2020-09-17 14:40:31.377232 number of SIP client 2020-09-17 14:40:31.377298 number of SIP server 2020-09-17 14:40:31.377384 SipDialogController 2020-09-17 14:40:31.377453 -------------------------- 2020-09-17 14:40:31.377518 m_mapIrq2IIP size: 2020-09-17 14:40:31.377585 m_mapOrq2IIP size: 2020-09-17 14:40:31.377651 m_mapTransactionId2IIP size: 2020-09-17 14:40:31.377718 m_mapLeg2Dialog size: 2020-09-17 14:40:31.377783 m_mapId2Dialog size: 2020-09-17 14:40:31.377850 m_mapOrq2RIP size: 2020-09-17 14:40:31.377944 number of outgoing 2020-09-17 14:40:31.378013 number of outgoing 2020-09-17 14:40:31.378082 general queue size: 2020-09-17 14:40:31.378150 timer A queue size: 2020-09-17 14:40:31.378219 timer B queue size: 2020-09-17 14:40:31.378286 timer C queue size: 2020-09-17 14:40:31.378354 timer D queue size: 2020-09-17 14:40:31.378462 timer E queue size: 2020-09-17 14:40:31.378535 timer F queue size: 2020-09-17 14:40:31.378603 timer G queue size: 2020-09-17 14:40:31.378670 timer K queue size: 2020-09-17 14:40:31.378747 ClientController 2020-09-17 14:40:31.378816 -------------------------- 2020-09-17 14:40:31.378882 m_clients size: 2020-09-17 14:40:31.378948 m_services size: 2020-09-17 14:40:31.379013 m_request_types size: 2020-09-17 14:40:31.379079 m_map_of_request_type_offsets size: 2020-09-17 14:40:31.379143 m_mapDialogs size: 2020-09-17 14:40:31.379226 m_mapNetTransactions size: 2020-09-17 14:40:31.379278 m_mapAppTransactions size: 2020-09-17 14:40:31.379325 m_mapApiRequests size: 2020-09-17 14:40:31.379381 m_mapDialogId2Appname size: 2020-09-17 14:40:31.379442 PendingRequestController 2020-09-17 14:40:31.379501 -------------------------- 2020-09-17 14:40:31.379558 m_mapCallId2Invite size: 2020-09-17 14:40:31.379616 m_mapTxnId2Invite size: 2020-09-17 14:40:31.379675 SipProxyController 2020-09-17 14:40:31.379731 -------------------------- 2020-09-17 14:40:31.379787 m_mapCallId2Proxy size: 2020-09-17 14:40:31.379845 m_mapNonce2Challenge size: 2020-09-17 14:40:31.379902 general queue size: 2020-09-17 14:40:31.379959 timer A queue size: 2020-09-17 14:40:31.380017 timer B queue size: 2020-09-17 14:40:31.380068 timer C queue size: 2020-09-17 14:40:31.380117 timer D queue size: 2020-09-17 14:40:31.380173 timer E queue size: 2020-09-17 14:40:31.380231 timer F queue size: 2020-09-17 14:40:31.380283 timer G queue size: 2020-09-17 14:40:31.380339 timer K queue size: 2020-09-17 14:40:31.380399 m_mapUri2InvalidData size: 2020-09-17 14:40:48.557101 nta.c:7316 _nta_incoming_timer() 2020-09-17 14:40:48.557365 nta.c:5983 incoming_reclaim_queued() 2020-09-17 14:40:48.557520 nta.c:7338 _nta_incoming_timer() 2020-09-17 14:40:48.557621 nta.c:1357 agent_timer() 2020-09-17 14:40:49.208602 nta.c:7316 _nta_incoming_timer() 2020-09-17 14:40:49.208849 nta.c:5983 incoming_reclaim_queued() 2020-09-17 14:40:49.208982 nta.c:7338 _nta_incoming_timer() 2020-09-17 14:40:49.209066 nta.c:1350 agent_timer() 2020-09-17 14:41:01.386530 DrachtioController::proces 2020-09-17 14:41:01.386818 size of hash table 2020-09-17 14:41:01.387022 size of hash table 2020-09-17 14:41:01.387144 size of hash table for dialogs 2020-09-17 14:41:01.387258 number of server-side 2020-09-17 14:41:01.387387 number of client-side 2020-09-17 14:41:01.387504 number of dialogs in the hash table 2020-09-17 14:41:01.387605 number of sip messages received 2020-09-17 14:41:01.387690 number of sip messages sent 2020-09-17 14:41:01.387775 number of sip requests received 2020-09-17 14:41:01.387833 number of sip requests sent 2020-09-17 14:41:01.387878 number of bad sip messages received 2020-09-17 14:41:01.387923 number of bad sip requests received 2020-09-17 14:41:01.387967 number of bad sip requests dropped 2020-09-17 14:41:01.388012 number of bad sip reponses dropped 2020-09-17 14:41:01.388055 number of client transactions created 2020-09-17 14:41:01.388099 number of server transactions created 2020-09-17 14:41:01.388143 number of in-dialog 2020-09-17 14:41:01.388188 number of server 2020-09-17 14:41:01.388232 number of server 2020-09-17 14:41:01.388277 number of requests 2020-09-17 14:41:01.388321 number of requests 2020-09-17 14:41:01.388365 number of responses 2020-09-17 14:41:01.388409 number of successful 2020-09-17 14:41:01.388453 number of requests merged by UAS 2020-09-17 14:41:01.388498 number of SIP responses sent by stack 2020-09-17 14:41:01.388542 number of SIP requests 2020-09-17 14:41:01.388586 number of SIP responses 2020-09-17 14:41:01.388630 number of retransmitted 2020-09-17 14:41:01.388674 number of SIP client 2020-09-17 14:41:01.388718 number of SIP server 2020-09-17 14:41:01.388784 SipDialogController 2020-09-17 14:41:01.388831 -------------------------- 2020-09-17 14:41:01.388875 m_mapIrq2IIP size: 2020-09-17 14:41:01.388920 m_mapOrq2IIP size: 2020-09-17 14:41:01.388965 m_mapTransactionId2IIP size: 2020-09-17 14:41:01.389010 m_mapLeg2Dialog size: 2020-09-17 14:41:01.389054 m_mapId2Dialog size: 2020-09-17 14:41:01.389099 m_mapOrq2RIP size: 2020-09-17 14:41:01.389143 number of outgoing 2020-09-17 14:41:01.389188 number of outgoing 2020-09-17 14:41:01.389263 general queue size: 2020-09-17 14:41:01.389315 timer A queue size: 2020-09-17 14:41:01.389361 timer B queue size: 2020-09-17 14:41:01.389407 timer C queue size: 2020-09-17 14:41:01.389453 timer D queue size: 2020-09-17 14:41:01.389499 timer E queue size: 2020-09-17 14:41:01.389544 timer F queue size: 2020-09-17 14:41:01.389589 timer G queue size: 2020-09-17 14:41:01.389634 timer K queue size: 2020-09-17 14:41:01.389691 ClientController 2020-09-17 14:41:01.389738 -------------------------- 2020-09-17 14:41:01.389781 m_clients size: 2020-09-17 14:41:01.389826 m_services size: 2020-09-17 14:41:01.389870 m_request_types size: 2020-09-17 14:41:01.389915 m_map_of_request_type_offsets size: 2020-09-17 14:41:01.389960 m_mapDialogs size: 2020-09-17 14:41:01.390004 m_mapNetTransactions size: 2020-09-17 14:41:01.390048 m_mapAppTransactions size: 2020-09-17 14:41:01.390093 m_mapApiRequests size: 2020-09-17 14:41:01.390138 m_mapDialogId2Appname size: 2020-09-17 14:41:01.390185 PendingRequestController 2020-09-17 14:41:01.390231 -------------------------- 2020-09-17 14:41:01.390276 m_mapCallId2Invite size: 2020-09-17 14:41:01.390321 m_mapTxnId2Invite size: 2020-09-17 14:41:01.390368 SipProxyController 2020-09-17 14:41:01.390467 -------------------------- 2020-09-17 14:41:01.390519 m_mapCallId2Proxy size: 2020-09-17 14:41:01.390604 m_mapNonce2Challenge size: 2020-09-17 14:41:01.390706 general queue size: 2020-09-17 14:41:01.390804 timer A queue size: 2020-09-17 14:41:01.390901 timer B queue size: 2020-09-17 14:41:01.390999 timer C queue size: 2020-09-17 14:41:01.391099 timer D queue size: 2020-09-17 14:41:01.391191 timer E queue size: 2020-09-17 14:41:01.391315 timer F queue size: 2020-09-17 14:41:01.391427 timer G queue size: 2020-09-17 14:41:01.391532 timer K queue size: 2020-09-17 14:41:01.391647 m_mapUri2InvalidData size: 2020-09-17 14:41:31.020359 tport.c:2769 tport_wakeup_pri() 2020-09-17 14:41:31.020587 tport.c:2892 tport_recv_event() 2020-09-17 14:41:31.020728 tport.c:3229 tport_recv_iovec() 2020-09-17 14:41:31.021191 recv 2033 bytes from MESSAGE sip:mcptt-as-mcla-1.ims.mnc001.mcc001.3gppnetwork.org Via: SIP/2.0/UDP ..33.81:35354;rport;branch= Max-Forwards: 70 From: sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=FS6Dy6cA2w6N5IEfV.I2s5DAIa1brPM- k.org> .81:35354;ob">sip:mcx.test-111.mcla@*.*.33.81:35354;ob;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mcptt";+g.3gpp.mcptt ;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mcdata.sds";require;explicit mcdata.sds 1.mcla@ims.mnc001.mcc001.3gppnetwork.org">sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org NOTIFY, PRACK, UPDATE, REFER a1MjpDCNgk.5VyoxE.

--evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/resource-lists+xml Content-Length: 275

<?xml version="1.0" encoding="UTF-8"?>

--evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/vnd.3gpp.mcdata-info+xml Content-Length: 143

one-to-one-sds

--evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/vnd.3gpp.mcdata-signalling Content-Length: 39

2020-09-17 14:41:31.021527 *** message truncated at 1831 *** 2020-09-17 14:41:31.021623 tport.c:3047 tport_deliver() tport_deliver(0x55d6bfca7680): msg 0x55d6bfcbbbe0 (2033 bytes) from udp/*.*.33.81:5060 next=(nil) 2020-09-17 14:41:31.021715 nta.c:3036 agent_recv_request() nta: received MESSAGE sip:mcptt-as-mcla-1.ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 (CSeq 44412) 2020-09-17 14:41:31.021825 nta.c:3253 agent_recv_request() nta: MESSAGE (44412) to message callback 2020-09-17 14:41:31.021921 processMessageStatelessly - incoming message with call-id RGGKUvfSwFgAdYZ06tRebVEPjoEE-Teg does not match an existing call leg, processed in thread 140391939795328 2020-09-17 14:41:31.022029 ClientController::selectClientForRequestOutsideDialog - there are 1 possible clients, we are starting with offset 0 2020-09-17 14:41:31.022108 ClientController::route_request_outside_dialog - Selected client at offset 0 2020-09-17 14:41:31.022239 PendingRequestController::add - tport: 0x55d6bfca7680, Call-ID: RGGKUvfSwFgAdYZ06tRebVEPjoEE-Teg, transactionId 0bd6a5b7-3eff-4b09-9463-03eb46acaf9c 2020-09-17 14:41:31.022321 pending-request: Adding entry to go off in 64000ms 2020-09-17 14:41:31.022437 pending-request: Adding entry to the head (queue was empty), length: 1 2020-09-17 14:41:31.022562 ClientController::addNetTransaction: transactionId 0bd6a5b7-3eff-4b09-9463-03eb46acaf9c; size: 1 2020-09-17 14:41:31.022924 Client::write_handler - wrote 2191 bytes: system:0 2020-09-17 14:41:31.386527 DrachtioController::processWatchdogTimer 2020-09-17 14:41:31.386754 size of hash table for server-side transactions 31 2020-09-17 14:41:31.386855 size of hash table for client-side transactions 31 2020-09-17 14:41:31.386932 size of hash table for dialogs 31 2020-09-17 14:41:31.387009 number of server-side transactions in the hash table 0 2020-09-17 14:41:31.387066 number of client-side transactions in the hash table 0 2020-09-17 14:41:31.387115 number of dialogs in the hash table 0 2020-09-17 14:41:31.387164 number of sip messages received 9 2020-09-17 14:41:31.387211 number of sip messages sent 8 2020-09-17 14:41:31.387255 number of sip requests received 9 2020-09-17 14:41:31.387298 number of sip requests sent 0 2020-09-17 14:41:31.387341 number of bad sip messages received 0 2020-09-17 14:41:31.387411 number of bad sip requests received 0 2020-09-17 14:41:31.387458 number of bad sip requests dropped 0 2020-09-17 14:41:31.387501 number of bad sip reponses dropped 0 2020-09-17 14:41:31.387545 number of client transactions created 0 2020-09-17 14:41:31.387588 number of server transactions created 6 2020-09-17 14:41:31.387631 number of in-dialog server transactions created 0 2020-09-17 14:41:31.387674 number of server transactions that have received ack 0 2020-09-17 14:41:31.387717 number of server transactions that have received cancel 0 2020-09-17 14:41:31.387760 number of requests that were processed stateless 9 2020-09-17 14:41:31.387803 number of requests converted to transactions by message callback 0 2020-09-17 14:41:31.387845 number of responses without matching request 0 2020-09-17 14:41:31.387888 number of successful responses missing INVITE client transaction 0 2020-09-17 14:41:31.387931 number of requests merged by UAS 0 2020-09-17 14:41:31.387974 number of SIP responses sent by stack 8 2020-09-17 14:41:31.388017 number of SIP requests retransmitted by stack 0 2020-09-17 14:41:31.388060 number of SIP responses retransmitted by stack 0 2020-09-17 14:41:31.388102 number of retransmitted SIP requests received by stack 0 2020-09-17 14:41:31.388145 number of SIP client transactions that has timeout 0 2020-09-17 14:41:31.388188 number of SIP server transactions that has timeout 0 2020-09-17 14:41:31.388250 SipDialogController storage counts 2020-09-17 14:41:31.388302 ---------------------------------- 2020-09-17 14:41:31.388353 m_mapIrq2IIP size: 0 2020-09-17 14:41:31.388397 m_mapOrq2IIP size: 0 2020-09-17 14:41:31.388441 m_mapTransactionId2IIP size: 0 2020-09-17 14:41:31.388485 m_mapLeg2Dialog size: 0 2020-09-17 14:41:31.388529 m_mapId2Dialog size: 0 2020-09-17 14:41:31.388572 m_mapOrq2RIP size: 0 2020-09-17 14:41:31.388616 number of outgoing transactions held for timerD: 0 2020-09-17 14:41:31.388659 number of outgoing transactions waiting for ACK from app: 0 2020-09-17 14:41:31.388704 general queue size: 0 2020-09-17 14:41:31.388751 timer A queue size: 0 2020-09-17 14:41:31.388796 timer B queue size: 0 2020-09-17 14:41:31.388841 timer C queue size: 0 2020-09-17 14:41:31.388886 timer D queue size: 0 2020-09-17 14:41:31.388931 timer E queue size: 0 2020-09-17 14:41:31.388975 timer F queue size: 0 2020-09-17 14:41:31.389019 timer G queue size: 0 2020-09-17 14:41:31.389063 timer K queue size: 0 2020-09-17 14:41:31.389116 ClientController storage counts 2020-09-17 14:41:31.389162 ---------------------------------- 2020-09-17 14:41:31.389205 m_clients size: 1 2020-09-17 14:41:31.389249 m_services size: 0 2020-09-17 14:41:31.389292 m_request_types size: 3 2020-09-17 14:41:31.389336 m_map_of_request_type_offsets size: 3 2020-09-17 14:41:31.389380 m_mapDialogs size: 0 2020-09-17 14:41:31.389436 m_mapNetTransactions size: 1 2020-09-17 14:41:31.389493 m_mapAppTransactions size: 0 2020-09-17 14:41:31.389540 m_mapApiRequests size: 0 2020-09-17 14:41:31.389592 m_mapDialogId2Appname size: 0 2020-09-17 14:41:31.389642 PendingRequestController storage counts 2020-09-17 14:41:31.389687 ---------------------------------- 2020-09-17 14:41:31.389731 m_mapCallId2Invite size: 1 2020-09-17 14:41:31.389775 m_mapTxnId2Invite size: 1 2020-09-17 14:41:31.389820 SipProxyController storage counts 2020-09-17 14:41:31.389864 ---------------------------------- 2020-09-17 14:41:31.389907 m_mapCallId2Proxy size: 0 2020-09-17 14:41:31.389951 m_mapNonce2Challenge size: 0 2020-09-17 14:41:31.389995 general queue size: 0 2020-09-17 14:41:31.390039 timer A queue size: 0 2020-09-17 14:41:31.390083 timer B queue size: 0 2020-09-17 14:41:31.390127 timer C queue size: 0 2020-09-17 14:41:31.390171 timer D queue size: 0 2020-09-17 14:41:31.390214 timer E queue size: 0 2020-09-17 14:41:31.390257 timer F queue size: 0 2020-09-17 14:41:31.390301 timer G queue size: 0 2020-09-17 14:41:31.390345 timer K queue size: 0 2020-09-17 14:41:31.390412 m_mapUri2InvalidData size: 0 2020-09-17 14:41:31.519054 tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x55d6bfca7680): events IN 2020-09-17 14:41:31.519273 tport.c:2892 tport_recv_event() tport_recv_event(0x55d6bfca7680) 2020-09-17 14:41:31.519449 tport.c:3229 tport_recv_iovec() tport_recv_iovec(0x55d6bfca7680) msg 0x55d6bfcc00b0 from (udp/*.*.46.7:5060) has 2033 bytes, veclen = 1 2020-09-17 14:41:31.519977 recv 2033 bytes from udp/[*.*.33.81]:35354 at 14:41:31.519590: MESSAGE sip:mcptt-as-mcla-1.ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 Via: SIP/2.0/UDP *.*.33.81:35354;rport;branch=z9hG4bKPjAt8iEdPAMwOwM2kh2KZ10D5KxTNPZNAB Max-Forwards: 70 From: ;tag=FS6Dy6cA2w6N5IEfV.I2s5DAIa1brPM- To: Call-ID: RGGKUvfSwFgAdYZ06tRebVEPjoEE-Teg CSeq: 44412 MESSAGE User-Agent: TEST e-TBS Contact: ;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mcptt";+g.3gpp.mcptt Accept-Contact: *;+g.3gpp.mcdata.sds;require;explicit;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mcdata.sds";require;explicit P-Preferred-Service: urn:urn-7:3gpp-service.ims.icsi.mcdata.sds Answer-Mode: Manual P-Preferred-Identity: Session-Expires: 3600 Allow: INVITE, ACK, CANCEL, BYE, MESSAGE, OPTIONS, NOTIFY, PRACK, UPDATE, REFER Content-Type: multipart/mixed;boundary=evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Length: 962 --evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/resource-lists+xml Content-Length: 275 --evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/vnd.3gpp.mcdata-info+xml Content-Length: 143

one-to-one-sds

--evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/vnd.3gpp.mcdata-signalling Content-Length: 39 2020-09-17 14:41:31.520277 *** message truncated at 1831 *** 2020-09-17 14:41:31.520374 tport.c:3047 tport_deliver() tport_deliver(0x55d6bfca7680): msg 0x55d6bfcc00b0 (2033 bytes) from udp/*.*.33.81:5060 next=(nil) 2020-09-17 14:41:31.520486 nta.c:3036 agent_recv_request() nta: received MESSAGE sip:mcptt-as-mcla-1.ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 (CSeq 44412) 2020-09-17 14:41:31.520615 nta.c:3253 agent_recv_request() nta: MESSAGE (44412) to message callback 2020-09-17 14:41:31.520730 processMessageStatelessly - incoming message with call-id RGGKUvfSwFgAdYZ06tRebVEPjoEE-Teg does not match an existing call leg, processed in thread 140391939795328 2020-09-17 14:41:31.520842 discarding retransmitted request: RGGKUvfSwFgAdYZ06tRebVEPjoEE-Teg

p-akshay commented 3 years ago

Corresponding MESSAGE from Wireshark is

MESSAGE sip:mcptt-as-mcla-1.ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 Via: SIP/2.0/UDP ..33.81:35354;rport;branch=z9hG4bKPjAt8iEdPAMwOwM2kh2KZ10D5KxTNPZNAB Max-Forwards: 70 From: sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=FS6Dy6cA2w6N5IEfV.I2s5DAIa1brPM- To: Call-ID: RGGKUvfSwFgAdYZ06tRebVEPjoEE-Teg CSeq: 44412 MESSAGE User-Agent: TEST e-TBS Contact: sip:mcx.test-111.mcla@*.*.33.81:35354;ob;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mcptt";+g.3gpp.mcptt Accept-Contact: *;+g.3gpp.mcdata.sds;require;explicit;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mcdata.sds";require;explicit P-Preferred-Service: urn:urn-7:3gpp-service.ims.icsi.mcdata.sds Answer-Mode: Manual P-Preferred-Identity: sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org Session-Expires: 3600 Allow: INVITE, ACK, CANCEL, BYE, MESSAGE, OPTIONS, NOTIFY, PRACK, UPDATE, REFER Content-Type: multipart/mixed;boundary=evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Length: 962

--evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/resource-lists+xml Content-Length: 275

<?xml version="1.0" encoding="UTF-8"?>

--evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/vnd.3gpp.mcdata-info+xml Content-Length: 143

one-to-one-sds

--evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/vnd.3gpp.mcdata-signalling Content-Length: 39

_c(B --evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/vnd.3gpp.mcdata-payload Content-Length: 10

xTEST --evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE.--

davehorton commented 3 years ago

From this line:

2020-09-17 14:35:01.261563 SipTransport::logTransports - udp/172.23.46.1:5060 (sip:*:5060;transport=udp,tcp, external-ip: , local-net: ), mtu size: 1300

I can see that the mtu size has not been set to 4096 as suggested. Could you show me your drachtio.conf.xml file?

p-akshay commented 3 years ago

127.0.0.1 sip:*:5060;transport=udp,tcp

4096

sip-cli sipcli friendly-scanner Cisco-SIPGateway pplsip

sipvicious

false 127.0.0.1 /var/log/drachtio/drachtio.log /var/log/drachtio/archive 100 20

true

9

debug

p-akshay commented 3 years ago

I had changed the MTU as you had suggested

4096

davehorton commented 3 years ago

I'm sorry, the template example config is wrong, change this:

<mtu-size>4096</mtu-size>

to this

<udp-mtu>4096</udp-mtu>

p-akshay commented 3 years ago

ok...will check with this... Thanks

davehorton commented 3 years ago

You can confirm by checking to see this log message when you start the server:

DrachtioController::run mtu size for udp packets: 4096

p-akshay commented 3 years ago

now the udp MTU is set to 4096 2020-09-17 19:25:14.827302 DrachtioController::run mtu size for udp packets: 4096 but the issue still remains... 2020-09-17 19:39:56.488640 message truncated at 1831

Adding the logs here 2020-09-17 19:25:14.710368 Starting drachtio version v0.8.6-rc1-8-g98afb45b 2020-09-17 19:25:14.737045 Logging threshold: 5 2020-09-17 19:25:14.737254 DrachtioController::run: Main thread id: 140560800393600 2020-09-17 19:25:14.737365 DrachtioController::run listening for applications on tcp port 6765 and tls port 0 2020-09-17 19:25:14.826788 ClientController::ClientController done setting tls options: 2020-09-17 19:25:14.826974 Client controller thread id: 140560800393600 2020-09-17 19:25:14.827174 ClientController::start_accept_tcp 2020-09-17 19:25:14.827302 DrachtioController::run mtu size for udp packets: 4096 2020-09-17 19:25:14.827399 responding to Prometheus on 127.0.0.1:8088 2020-09-17 19:25:14.827469 Client controller thread id: 140560800388864 2020-09-17 19:25:14.827701 ClientController::threadFunc - ClientController: io_context run loop started (or restarted) 2020-09-17 19:25:14.851442 tcp keep alives will be sent to clients every 45 seconds 2020-09-17 19:25:14.853506 DrachtioController::run: starting sip stack on sip::5060;transport=udp,tcp 2020-09-17 19:25:14.853635 SipTransport::getBindableContactUri: sip::5060;transport=udp,tcp 2020-09-17 19:25:14.854370 nta.c:968 nta_agent_create() nta_agent_create: initialized hash tables 2020-09-17 19:25:14.855125 tport.c:516 tport_tcreate() tport_create(): 0x556bff73e170 2020-09-17 19:25:14.855333 nta.c:2382 agent_create_master_transport() nta: master transport created 2020-09-17 19:25:14.855577 tport.c:1642 tport_bind_server() tport_bind_server(0x556bff73e170) to /:5060 2020-09-17 19:25:14.856295 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for udp 2020-09-17 19:25:14.856466 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff73ef80 2020-09-17 19:25:14.856745 tport.c:767 tport_listen() tport_listen(0x556bff73ef80): listening at udp/182.58.137.173:5060 2020-09-17 19:25:14.856850 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for tcp 2020-09-17 19:25:14.856924 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff73f460 2020-09-17 19:25:14.857099 tport.c:767 tport_listen() tport_listen(0x556bff73f460): listening at tcp/182.58.137.173:5060 2020-09-17 19:25:14.857185 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for udp 2020-09-17 19:25:14.857255 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff73f930 2020-09-17 19:25:14.857426 tport.c:767 tport_listen() tport_listen(0x556bff73f930): listening at udp/192.168.1.23:5060 2020-09-17 19:25:14.857540 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for tcp 2020-09-17 19:25:14.857638 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff73fe30 2020-09-17 19:25:14.857814 tport.c:767 tport_listen() tport_listen(0x556bff73fe30): listening at tcp/192.168.1.23:5060 2020-09-17 19:25:14.857926 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for udp 2020-09-17 19:25:14.858024 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff740300 2020-09-17 19:25:14.858201 tport.c:767 tport_listen() tport_listen(0x556bff740300): listening at udp/10.101.27.2:5060 2020-09-17 19:25:14.858324 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for tcp 2020-09-17 19:25:14.858429 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff740800 2020-09-17 19:25:14.858624 tport.c:767 tport_listen() tport_listen(0x556bff740800): listening at tcp/10.101.27.2:5060 2020-09-17 19:25:14.858719 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for udp 2020-09-17 19:25:14.858823 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff740cd0 2020-09-17 19:25:14.859096 tport.c:767 tport_listen() tport_listen(0x556bff740cd0): listening at udp/..46.1:5060 2020-09-17 19:25:14.859231 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for tcp 2020-09-17 19:25:14.859333 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff7411d0 2020-09-17 19:25:14.859541 tport.c:767 tport_listen() tport_listen(0x556bff7411d0): listening at tcp/..46.1:5060 2020-09-17 19:25:14.859659 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for udp 2020-09-17 19:25:14.859736 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff7416a0 2020-09-17 19:25:14.859931 tport.c:767 tport_listen() tport_listen(0x556bff7416a0): listening at udp/..46.7:5060 2020-09-17 19:25:14.860020 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for tcp 2020-09-17 19:25:14.860077 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff741ec0 2020-09-17 19:25:14.860207 tport.c:767 tport_listen() tport_listen(0x556bff741ec0): listening at tcp/..46.7:5060 2020-09-17 19:25:14.860304 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for udp 2020-09-17 19:25:14.860391 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff742370 2020-09-17 19:25:14.860630 tport.c:767 tport_listen() tport_listen(0x556bff742370): listening at udp/127.0.0.1:5060 2020-09-17 19:25:14.860741 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for tcp 2020-09-17 19:25:14.860835 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff742820 2020-09-17 19:25:14.861002 tport.c:767 tport_listen() tport_listen(0x556bff742820): listening at tcp/127.0.0.1:5060 2020-09-17 19:25:14.861123 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for udp 2020-09-17 19:25:14.861217 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff742cd0 2020-09-17 19:25:14.861509 tport.c:767 tport_listen() tport_listen(0x556bff742cd0): listening at udp/[::1]:5060 2020-09-17 19:25:14.861638 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for tcp 2020-09-17 19:25:14.861735 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff743180 2020-09-17 19:25:14.861925 tport.c:767 tport_listen() tport_listen(0x556bff743180): listening at tcp/[::1]:5060 2020-09-17 19:25:14.862045 nta.c:2336 nta_agent_add_tport() nta: bound to (:5060;transport=) 2020-09-17 19:25:14.862153 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp 182.58.137.173 () 2020-09-17 19:25:14.862270 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 182.58.137.173 () 2020-09-17 19:25:14.862422 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp 192.168.1.23 () 2020-09-17 19:25:14.862532 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 192.168.1.23 () 2020-09-17 19:25:14.862640 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp 10.101.27.2 () 2020-09-17 19:25:14.862745 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 10.101.27.2 () 2020-09-17 19:25:14.862834 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp ..46.1 () 2020-09-17 19:25:14.862937 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp ..46.1 () 2020-09-17 19:25:14.863043 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp ..46.7 () 2020-09-17 19:25:14.863148 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp ..46.7 () 2020-09-17 19:25:14.863256 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp 127.0.0.1 () 2020-09-17 19:25:14.863374 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 127.0.0.1 () 2020-09-17 19:25:14.863493 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp [::1] () 2020-09-17 19:25:14.863610 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp [::1] () 2020-09-17 19:25:14.863852 nta.c:2350 nta_agent_add_tport() nta: Via fields initialized 2020-09-17 19:25:14.864601 nta.c:2358 nta_agent_add_tport() nta: Contact header created 2020-09-17 19:25:14.864774 nta.c:975 nta_agent_create() nta_agent_create: initialized transports 2020-09-17 19:25:14.864886 nta.c:981 nta_agent_create() nta_agent_create: initialized random identifiers 2020-09-17 19:25:14.865034 nta.c:987 nta_agent_create() nta_agent_create: initialized timer 2020-09-17 19:25:14.865395 nta.c:997 nta_agent_create() nta_agent_create: initialized resolver 2020-09-17 19:25:14.866936 SipTransport::addTransports - creating transport: 0x556bff73ef80: udp/182.58.137.173:5060 2020-09-17 19:25:14.867724 SipTransport::addTransports - creating transport: 0x556bff73f460: tcp/182.58.137.173:5060 2020-09-17 19:25:14.868464 SipTransport::addTransports - creating transport: 0x556bff73f930: udp/192.168.1.23:5060 2020-09-17 19:25:14.869192 SipTransport::addTransports - creating transport: 0x556bff73fe30: tcp/192.168.1.23:5060 2020-09-17 19:25:14.869923 SipTransport::addTransports - creating transport: 0x556bff740300: udp/10.101.27.2:5060 2020-09-17 19:25:14.870697 SipTransport::addTransports - creating transport: 0x556bff740800: tcp/10.101.27.2:5060 2020-09-17 19:25:14.871442 SipTransport::addTransports - creating transport: 0x556bff740cd0: udp/..46.1:5060 2020-09-17 19:25:14.872223 SipTransport::addTransports - creating transport: 0x556bff7411d0: tcp/..46.1:5060 2020-09-17 19:25:14.872789 SipTransport::addTransports - creating transport: 0x556bff7416a0: udp/..46.7:5060 2020-09-17 19:25:14.873333 SipTransport::addTransports - creating transport: 0x556bff741ec0: tcp/..46.7:5060 2020-09-17 19:25:14.873879 SipTransport::addTransports - creating transport: 0x556bff742370: udp/127.0.0.1:5060 2020-09-17 19:25:14.874511 SipTransport::addTransports - creating transport: 0x556bff742820: tcp/127.0.0.1:5060 2020-09-17 19:25:14.875120 SipTransport::addTransports - creating transport: 0x556bff742cd0: udp/[::1]:5060 2020-09-17 19:25:14.875687 SipTransport::addTransports - creating transport: 0x556bff743180: tcp/[::1]:5060 2020-09-17 19:25:14.876239 DrachtioController::run: adding additional sip address sip:192.168.1.23:5066;transport=ws 2020-09-17 19:25:14.876274 SipTransport::getBindableContactUri: sip:192.168.1.23:5066;transport=ws 2020-09-17 19:25:14.876313 tport.c:1642 tport_bind_server() tport_bind_server(0x556bff73e170) to ws/192.168.1.23:5066 2020-09-17 19:25:14.876350 tport.c:1712 tport_bind_server() tport_bind_server(0x556bff73e170): calling tport_listen for ws 2020-09-17 19:25:14.876379 tport.c:638 tport_alloc_primary() tport_alloc_primary(0x556bff73e170): new primary tport 0x556bff7498e0 2020-09-17 19:25:14.876454 tport.c:767 tport_listen() tport_listen(0x556bff7498e0): listening at ws/192.168.1.23:5066 2020-09-17 19:25:14.876487 nta.c:2336 nta_agent_add_tport() nta: bound to (192.168.1.23:5066;transport=ws) 2020-09-17 19:25:14.876521 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp 182.58.137.173 () 2020-09-17 19:25:14.876553 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 182.58.137.173 () 2020-09-17 19:25:14.876582 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp 192.168.1.23 () 2020-09-17 19:25:14.876615 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 192.168.1.23 () 2020-09-17 19:25:14.876644 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp 10.101.27.2 () 2020-09-17 19:25:14.876673 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 10.101.27.2 () 2020-09-17 19:25:14.876702 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp ..46.1 () 2020-09-17 19:25:14.876734 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp ..46.1 () 2020-09-17 19:25:14.876772 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp ..46.7 () 2020-09-17 19:25:14.876823 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp ..46.7 () 2020-09-17 19:25:14.876886 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp 127.0.0.1 () 2020-09-17 19:25:14.876932 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 127.0.0.1 () 2020-09-17 19:25:14.876977 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/udp [::1] () 2020-09-17 19:25:14.877022 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/tcp [::1] () 2020-09-17 19:25:14.877069 nta.c:2478 agent_init_via() nta: agent_init_via: SIP/2.0/ws 192.168.1.23:5066 () 2020-09-17 19:25:14.877154 nta.c:2350 nta_agent_add_tport() nta: Via fields initialized 2020-09-17 19:25:14.877192 nta.c:2358 nta_agent_add_tport() nta: Contact header created 2020-09-17 19:25:14.877688 SipTransport::addTransports - creating transport: 0x556bff7498e0: ws/192.168.1.23:5066 2020-09-17 19:25:14.878157 SipTransport::logTransports - there are : 15 transports 2020-09-17 19:25:14.878197 SipTransport::logTransports - ws/192.168.1.23:5066 (sip:192.168.1.23:5066;transport=ws, external-ip: , local-net: ) 2020-09-17 19:25:14.878236 SipTransport::logTransports - tcp/[::1]:5060 (sip::5060;transport=udp,tcp, external-ip: , local-net: ) 2020-09-17 19:25:14.878298 SipTransport::logTransports - udp/182.58.137.173:5060 (sip::5060;transport=udp,tcp, external-ip: , local-net: ), mtu size: 4096 2020-09-17 19:25:14.878339 SipTransport::logTransports - tcp/182.58.137.173:5060 (sip::5060;transport=udp,tcp, external-ip: , local-net: ) 2020-09-17 19:25:14.878381 SipTransport::logTransports - udp/10.101.27.2:5060 (sip::5060;transport=udp,tcp, external-ip: , local-net: 10.0.0.0/8), mtu size: 4096 2020-09-17 19:25:14.878421 SipTransport::logTransports - udp/192.168.1.23:5060 (sip::5060;transport=udp,tcp, external-ip: , local-net: ), mtu size: 4096 2020-09-17 19:25:14.878463 SipTransport::logTransports - udp/127.0.0.1:5060 (sip::5060;transport=udp,tcp, external-ip: , local-net: 127.0.0.1/32), mtu size: 4096 2020-09-17 19:25:14.878499 SipTransport::logTransports - tcp/192.168.1.23:5060 (sip::5060;transport=udp,tcp, external-ip: , local-net: ) 2020-09-17 19:25:14.878540 SipTransport::logTransports - udp/..46.1:5060 (sip::5060;transport=udp,tcp, external-ip: , local-net: ), mtu size: 4096 2020-09-17 19:25:14.878589 SipTransport::logTransports - tcp/10.101.27.2:5060 (sip::5060;transport=udp,tcp, external-ip: , local-net: 10.0.0.0/8) 2020-09-17 19:25:14.878627 SipTransport::logTransports - udp/..46.7:5060 (sip::5060;transport=udp,tcp, external-ip: , local-net: ), mtu size: 4096 2020-09-17 19:25:14.878666 SipTransport::logTransports - tcp/..46.7:5060 (sip::5060;transport=udp,tcp, external-ip: , local-net: ) 2020-09-17 19:25:14.878704 SipTransport::logTransports - tcp/..46.1:5060 (sip::5060;transport=udp,tcp, external-ip: , local-net: ) 2020-09-17 19:25:14.878742 SipTransport::logTransports - tcp/127.0.0.1:5060 (sip::5060;transport=udp,tcp, external-ip: , local-net: 127.0.0.1/32) 2020-09-17 19:25:14.878782 SipTransport::logTransports - udp/[::1]:5060 (sip:*:5060;transport=udp,tcp, external-ip: , local-net: ), mtu size: 4096 2020-09-17 19:25:14.878843 DrachtioController::run - sip timers: T1: 500ms, T2: 4000ms, T4: 5000ms, T1X64: 32000ms 2020-09-17 19:25:14.878931 Starting sofia event loop in main thread: 140560800393600 2020-09-17 19:25:25.449196 ClientController::accept_handler_tcp - got connection 2020-09-17 19:25:25.449315 Client::start - Received connection from client at 127.0.0.1:36574 2020-09-17 19:25:25.449353 ClientController::join - Added client, count of connected clients is now: 1 2020-09-17 19:25:25.449436 ClientController::start_accept_tcp 2020-09-17 19:25:25.454866 Client::read_handler read: 3a88b244-7862-4d3e-9e3c-f93fd0572f3c|authenticate|mc1@bs|

2020-09-17 19:25:25.454998 Client::processAuthentication - added tags 2020-09-17 19:25:25.455030 Client::processAuthentication - validating secret mc1@bs 2020-09-17 19:25:25.455102 Client::processAuthentication - secret validated successfully: mc1@bs 2020-09-17 19:25:25.455135 Sending response: 415#1be33f78-b77c-4a38-9a72-c755925b3244|response|3a88b244-7862-4d3e-9e3c-f93fd0572f3c|OK|ws/192.168.1.23:5066,tcp/[::1]:5060,udp/182.58.137.173:5060,tcp/182.58.137.173:5060,udp/10.101.27.2:5060,udp/192.168.1.23:5060,udp/127.0.0.1:5060,tcp/192.168.1.23:5060,udp/..46.1:5060,tcp/10.101.27.2:5060,udp/..46.7:5060,tcp/..46.7:5060,tcp/..46.1:5060,tcp/127.0.0.1:5060,udp/[::1]:5060|v0.8.6-rc1-8-g98afb45b

2020-09-17 19:25:25.455194 Client::write_handler - wrote 419 bytes: system:0 2020-09-17 19:25:25.459074 Client::read_handler read: d80edc09-3d21-41bb-aeaa-0e732abb60dd|route|register

2020-09-17 19:25:25.459161 Added client for register requests 2020-09-17 19:25:25.459227 Sending response: 85#4611e2b4-c735-4eb4-a7e8-6f8e8f2920bc|response|d80edc09-3d21-41bb-aeaa-0e732abb60dd|OK

2020-09-17 19:25:25.459296 Client::write_handler - wrote 88 bytes: system:0 2020-09-17 19:25:25.459332 Client::read_handler read: e5b9a8a2-1d1d-489d-8a0b-97476350bd3f|route|message

2020-09-17 19:25:25.459370 Added client for message requests 2020-09-17 19:25:25.459428 Sending response: 85#1171b582-6204-4037-b7e9-ea9052777a53|response|e5b9a8a2-1d1d-489d-8a0b-97476350bd3f|OK

2020-09-17 19:25:25.459481 Client::read_handler processing follow-on message in read buffer, remaining bytes to process: 52 2020-09-17 19:25:25.459518 Client::read_handler follow-on message length of 49 bytes 2020-09-17 19:25:25.459552 Client::read_handler read: a4b078bb-4771-45bf-b7f4-3af93c840d42|route|invite

2020-09-17 19:25:25.459590 Added client for invite requests 2020-09-17 19:25:25.459643 Sending response: 85#da33f77c-9f26-4e85-b3cb-8ecb7e5fe4b4|response|a4b078bb-4771-45bf-b7f4-3af93c840d42|OK

2020-09-17 19:25:25.459693 Client::write_handler - wrote 88 bytes: system:0 2020-09-17 19:25:25.459725 Client::write_handler - wrote 88 bytes: system:0 2020-09-17 19:25:44.894314 DrachtioController::processWatchdogTimer 2020-09-17 19:25:44.894473 size of hash table for server-side transactions 31 2020-09-17 19:25:44.894523 size of hash table for client-side transactions 31 2020-09-17 19:25:44.894558 size of hash table for dialogs 31 2020-09-17 19:25:44.894610 number of server-side transactions in the hash table 0 2020-09-17 19:25:44.894650 number of client-side transactions in the hash table 0 2020-09-17 19:25:44.894686 number of dialogs in the hash table 0 2020-09-17 19:25:44.894722 number of sip messages received 0 2020-09-17 19:25:44.894756 number of sip messages sent 0 2020-09-17 19:25:44.894791 number of sip requests received 0 2020-09-17 19:25:44.894829 number of sip requests sent 0 2020-09-17 19:25:44.894863 number of bad sip messages received 0 2020-09-17 19:25:44.894898 number of bad sip requests received 0 2020-09-17 19:25:44.894935 number of bad sip requests dropped 0 2020-09-17 19:25:44.894973 number of bad sip reponses dropped 0 2020-09-17 19:25:44.895010 number of client transactions created 0 2020-09-17 19:25:44.895046 number of server transactions created 0 2020-09-17 19:25:44.895082 number of in-dialog server transactions created 0 2020-09-17 19:25:44.895116 number of server transactions that have received ack 0 2020-09-17 19:25:44.895149 number of server transactions that have received cancel 0 2020-09-17 19:25:44.895184 number of requests that were processed stateless 0 2020-09-17 19:25:44.895219 number of requests converted to transactions by message callback 0 2020-09-17 19:25:44.895253 number of responses without matching request 0 2020-09-17 19:25:44.895287 number of successful responses missing INVITE client transaction 0 2020-09-17 19:25:44.895320 number of requests merged by UAS 0 2020-09-17 19:25:44.895355 number of SIP responses sent by stack 0 2020-09-17 19:25:44.895389 number of SIP requests retransmitted by stack 0 2020-09-17 19:25:44.895426 number of SIP responses retransmitted by stack 0 2020-09-17 19:25:44.895461 number of retransmitted SIP requests received by stack 0 2020-09-17 19:25:44.895494 number of SIP client transactions that has timeout 0 2020-09-17 19:25:44.895531 number of SIP server transactions that has timeout 0 2020-09-17 19:25:44.895611 SipDialogController storage counts 2020-09-17 19:25:44.895654 ---------------------------------- 2020-09-17 19:25:44.895690 m_mapIrq2IIP size: 0 2020-09-17 19:25:44.895726 m_mapOrq2IIP size: 0 2020-09-17 19:25:44.895760 m_mapTransactionId2IIP size: 0 2020-09-17 19:25:44.895796 m_mapLeg2Dialog size: 0 2020-09-17 19:25:44.895835 m_mapId2Dialog size: 0 2020-09-17 19:25:44.895883 m_mapOrq2RIP size: 0 2020-09-17 19:25:44.895920 number of outgoing transactions held for timerD: 0 2020-09-17 19:25:44.895957 number of outgoing transactions waiting for ACK from app: 0 2020-09-17 19:25:44.895992 general queue size: 0 2020-09-17 19:25:44.896028 timer A queue size: 0 2020-09-17 19:25:44.896065 timer B queue size: 0 2020-09-17 19:25:44.896102 timer C queue size: 0 2020-09-17 19:25:44.896139 timer D queue size: 0 2020-09-17 19:25:44.896177 timer E queue size: 0 2020-09-17 19:25:44.896213 timer F queue size: 0 2020-09-17 19:25:44.896264 timer G queue size: 0 2020-09-17 19:25:44.896302 timer K queue size: 0 2020-09-17 19:25:44.896346 ClientController storage counts 2020-09-17 19:25:44.896384 ---------------------------------- 2020-09-17 19:25:44.896417 m_clients size: 1 2020-09-17 19:25:44.896453 m_services size: 0 2020-09-17 19:25:44.896486 m_request_types size: 3 2020-09-17 19:25:44.896521 m_map_of_request_type_offsets size: 3 2020-09-17 19:25:44.896558 m_mapDialogs size: 0 2020-09-17 19:25:44.896594 m_mapNetTransactions size: 0 2020-09-17 19:25:44.896631 m_mapAppTransactions size: 0 2020-09-17 19:25:44.896667 m_mapApiRequests size: 0 2020-09-17 19:25:44.896704 m_mapDialogId2Appname size: 0 2020-09-17 19:25:44.896743 PendingRequestController storage counts 2020-09-17 19:25:44.896781 ---------------------------------- 2020-09-17 19:25:44.896816 m_mapCallId2Invite size: 0 2020-09-17 19:25:44.896850 m_mapTxnId2Invite size: 0 2020-09-17 19:25:44.896887 SipProxyController storage counts 2020-09-17 19:25:44.896922 ---------------------------------- 2020-09-17 19:25:44.896960 m_mapCallId2Proxy size: 0 2020-09-17 19:25:44.896995 m_mapNonce2Challenge size: 0 2020-09-17 19:25:44.897032 general queue size: 0 2020-09-17 19:25:44.897068 timer A queue size: 0 2020-09-17 19:25:44.897102 timer B queue size: 0 2020-09-17 19:25:44.897137 timer C queue size: 0 2020-09-17 19:25:44.897174 timer D queue size: 0 2020-09-17 19:25:44.897210 timer E queue size: 0 2020-09-17 19:25:44.897246 timer F queue size: 0 2020-09-17 19:25:44.897279 timer G queue size: 0 2020-09-17 19:25:44.897314 timer K queue size: 0 2020-09-17 19:25:44.897353 m_mapUri2InvalidData size: 0 2020-09-17 19:26:03.405174 tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x556bff7416a0): events IN 2020-09-17 19:26:03.405279 tport.c:2892 tport_recv_event() tport_recv_event(0x556bff7416a0) 2020-09-17 19:26:03.405341 tport.c:3229 tport_recv_iovec() tport_recv_iovec(0x556bff7416a0) msg 0x556bff74eb60 from (udp/..46.7:5060) has 767 bytes, veclen = 1 2020-09-17 19:26:03.432752 recv 767 bytes from udp/[..33.83]:53850 at 19:26:03.405386: REGISTER sip:ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 Via: SIP/2.0/UDP ..33.83:53850;rport;branch=z9hG4bKPj1xRdYQAqfgieaFc2nAcwbaX2XCumbHg4 Max-Forwards: 70 From: sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=gEDIFAQrNLGbRujhJsQ1tKt2hVJbgM22 To: sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org Call-ID: a.TdB1jqosJsnPa8.VWIVNuGX55ukW3Q CSeq: 37808 REGISTER P-Preferred-Identity: sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org User-Agent: TEST e-TBS Contact: sip:mcx.test-333.mcla@*.*.33.83:53850;ob;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mcptt";+g.3gpp.mcptt Expires: 300 Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Content-Length: 0

2020-09-17 19:26:03.433014 tport.c:3047 tport_deliver() tport_deliver(0x556bff7416a0): msg 0x556bff74eb60 (767 bytes) from udp/..33.83:5060 next=(nil) 2020-09-17 19:26:03.433200 nta.c:3036 agent_recv_request() nta: received REGISTER sip:ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 (CSeq 37808) 2020-09-17 19:26:03.433351 nta.c:3253 agent_recv_request() nta: REGISTER (37808) to message callback 2020-09-17 19:26:03.433482 processMessageStatelessly - incoming message with call-id a.TdB1jqosJsnPa8.VWIVNuGX55ukW3Q does not match an existing call leg, processed in thread 140560800393600 2020-09-17 19:26:03.433655 ClientController::selectClientForRequestOutsideDialog - there are 1 possible clients, we are starting with offset 0 2020-09-17 19:26:03.433757 ClientController::route_request_outside_dialog - Selected client at offset 0 2020-09-17 19:26:03.433879 PendingRequestController::add - tport: 0x556bff7416a0, Call-ID: a.TdB1jqosJsnPa8.VWIVNuGX55ukW3Q, transactionId aca1c42c-3a92-4c5c-89f2-fad87edf3af0 2020-09-17 19:26:03.468143 pending-request: Adding entry to go off in 64000ms 2020-09-17 19:26:03.468619 pending-request: Adding entry to the head (queue was empty), length: 1 2020-09-17 19:26:03.468802 ClientController::addNetTransaction: transactionId aca1c42c-3a92-4c5c-89f2-fad87edf3af0; size: 1 2020-09-17 19:26:03.469195 Client::write_handler - wrote 926 bytes: system:0 2020-09-17 19:26:03.485255 Client::read_handler read: e3438132-e96d-4d81-91f4-844c5cba164f|sip|aca1c42c-3a92-4c5c-89f2-fad87edf3af0| SIP/2.0 401 Unauthorized Call-ID: a.TdB1jqosJsnPa8.VWIVNuGX55ukW3Q cseq: 37808 REGISTER from: sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=gEDIFAQrNLGbRujhJsQ1tKt2hVJbgM22 to: sip:mcx.test-333.mcla@ims.mnc001.mcc001.3gppnetwork.org Content-Length: 0 www-authenticate: Digest realm="ims.mnc001.mcc001.3gppnetwork.org", algorithm=MD5, qop="auth", nonce="160035096348100"

p-akshay commented 3 years ago

2020-09-17 19:39:45.196086 DrachtioController::processWatchdogTimer 2020-09-17 19:39:45.196427 size of hash table for server-side transactions 31 2020-09-17 19:39:45.196574 size of hash table for client-side transactions 31 2020-09-17 19:39:45.196678 size of hash table for dialogs 31 2020-09-17 19:39:45.196786 number of server-side transactions in the hash table 2 2020-09-17 19:39:45.196863 number of client-side transactions in the hash table 0 2020-09-17 19:39:45.196932 number of dialogs in the hash table 0 2020-09-17 19:39:45.197001 number of sip messages received 12 2020-09-17 19:39:45.197069 number of sip messages sent 12 2020-09-17 19:39:45.197131 number of sip requests received 12 2020-09-17 19:39:45.197193 number of sip requests sent 0 2020-09-17 19:39:45.197263 number of bad sip messages received 0 2020-09-17 19:39:45.197335 number of bad sip requests received 0 2020-09-17 19:39:45.197398 number of bad sip requests dropped 0 2020-09-17 19:39:45.197462 number of bad sip reponses dropped 0 2020-09-17 19:39:45.197524 number of client transactions created 0 2020-09-17 19:39:45.197587 number of server transactions created 8 2020-09-17 19:39:45.197650 number of in-dialog server transactions created 0 2020-09-17 19:39:45.197723 number of server transactions that have received ack 0 2020-09-17 19:39:45.197791 number of server transactions that have received cancel 0 2020-09-17 19:39:45.197854 number of requests that were processed stateless 12 2020-09-17 19:39:45.197917 number of requests converted to transactions by message callback 0 2020-09-17 19:39:45.197979 number of responses without matching request 0 2020-09-17 19:39:45.198041 number of successful responses missing INVITE client transaction 0 2020-09-17 19:39:45.198104 number of requests merged by UAS 0 2020-09-17 19:39:45.198177 number of SIP responses sent by stack 12 2020-09-17 19:39:45.198245 number of SIP requests retransmitted by stack 0 2020-09-17 19:39:45.198370 number of SIP responses retransmitted by stack 0 2020-09-17 19:39:45.198474 number of retransmitted SIP requests received by stack 0 2020-09-17 19:39:45.198542 number of SIP client transactions that has timeout 0 2020-09-17 19:39:45.198603 number of SIP server transactions that has timeout 0 2020-09-17 19:39:45.198703 SipDialogController storage counts 2020-09-17 19:39:45.198773 ---------------------------------- 2020-09-17 19:39:45.198833 m_mapIrq2IIP size: 0 2020-09-17 19:39:45.198894 m_mapOrq2IIP size: 0 2020-09-17 19:39:45.198954 m_mapTransactionId2IIP size: 0 2020-09-17 19:39:45.199014 m_mapLeg2Dialog size: 0 2020-09-17 19:39:45.199090 m_mapId2Dialog size: 0 2020-09-17 19:39:45.199175 m_mapOrq2RIP size: 0 2020-09-17 19:39:45.199260 number of outgoing transactions held for timerD: 0 2020-09-17 19:39:45.199342 number of outgoing transactions waiting for ACK from app: 0 2020-09-17 19:39:45.199428 general queue size: 0 2020-09-17 19:39:45.199518 timer A queue size: 0 2020-09-17 19:39:45.199604 timer B queue size: 0 2020-09-17 19:39:45.199695 timer C queue size: 0 2020-09-17 19:39:45.199780 timer D queue size: 0 2020-09-17 19:39:45.199848 timer E queue size: 0 2020-09-17 19:39:45.199910 timer F queue size: 0 2020-09-17 19:39:45.199972 timer G queue size: 0 2020-09-17 19:39:45.200032 timer K queue size: 0 2020-09-17 19:39:45.200106 ClientController storage counts 2020-09-17 19:39:45.200168 ---------------------------------- 2020-09-17 19:39:45.200226 m_clients size: 1 2020-09-17 19:39:45.200287 m_services size: 0 2020-09-17 19:39:45.200346 m_request_types size: 3 2020-09-17 19:39:45.200405 m_map_of_request_type_offsets size: 3 2020-09-17 19:39:45.200475 m_mapDialogs size: 0 2020-09-17 19:39:45.200540 m_mapNetTransactions size: 0 2020-09-17 19:39:45.200611 m_mapAppTransactions size: 0 2020-09-17 19:39:45.200675 m_mapApiRequests size: 0 2020-09-17 19:39:45.200747 m_mapDialogId2Appname size: 0 2020-09-17 19:39:45.200815 PendingRequestController storage counts 2020-09-17 19:39:45.200877 ---------------------------------- 2020-09-17 19:39:45.200937 m_mapCallId2Invite size: 0 2020-09-17 19:39:45.201010 m_mapTxnId2Invite size: 0 2020-09-17 19:39:45.201077 SipProxyController storage counts 2020-09-17 19:39:45.201136 ---------------------------------- 2020-09-17 19:39:45.201194 m_mapCallId2Proxy size: 0 2020-09-17 19:39:45.201255 m_mapNonce2Challenge size: 0 2020-09-17 19:39:45.201329 general queue size: 0 2020-09-17 19:39:45.201344 timer A queue size: 0 2020-09-17 19:39:45.201363 timer B queue size: 0 2020-09-17 19:39:45.201380 timer C queue size: 0 2020-09-17 19:39:45.201395 timer D queue size: 0 2020-09-17 19:39:45.201415 timer E queue size: 0 2020-09-17 19:39:45.201431 timer F queue size: 0 2020-09-17 19:39:45.201446 timer G queue size: 0 2020-09-17 19:39:45.201461 timer K queue size: 0 2020-09-17 19:39:45.201478 m_mapUri2InvalidData size: 0 2020-09-17 19:39:48.730257 nta.c:7316 _nta_incoming_timer() nta: timer J fired, terminate 401 response 2020-09-17 19:39:48.730533 nta.c:5983 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7ffcbee9b2c0) 2020-09-17 19:39:48.730760 nta.c:7338 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free 2020-09-17 19:39:48.730907 nta.c:1357 agent_timer() nta: timer set next to 275 ms 2020-09-17 19:39:49.007654 nta.c:7316 _nta_incoming_timer() nta: timer J fired, terminate 200 response 2020-09-17 19:39:49.007890 nta.c:5983 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil), 0x7ffcbee9b2c0) 2020-09-17 19:39:49.008047 nta.c:7338 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free 2020-09-17 19:39:49.008159 nta.c:1350 agent_timer() nta: timer not set 2020-09-17 19:39:56.487753 tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x556bff7416a0): events IN 2020-09-17 19:39:56.487936 tport.c:2892 tport_recv_event() tport_recv_event(0x556bff7416a0) 2020-09-17 19:39:56.488043 tport.c:3229 tport_recv_iovec() tport_recv_iovec(0x556bff7416a0) msg 0x556bff761490 from (udp/..46.7:5060) has 2033 bytes, veclen = 1 2020-09-17 19:39:56.488378 recv 2033 bytes from udp/[..33.81]:57570 at 19:39:56.488128: MESSAGE sip:mcptt-as-mcla-1.ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 Via: SIP/2.0/UDP ..33.81:57570;rport;branch=z9hG4bKPjWyYL5ZsRwpSQXUd0U-HtHpAK9eIW4z7z Max-Forwards: 70 From: sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org;tag=dKAWd-RbsRFtqOFq2LhIvZylwU60PfvB To: Call-ID: c8oHzoxL8Lt.Prut0H9FJew9cduHCvvj CSeq: 58213 MESSAGE User-Agent: TEST e-TBS Contact: sip:mcx.test-111.mcla@*.*.33.81:57570;ob;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mcptt";+g.3gpp.mcptt Accept-Contact: *;+g.3gpp.mcdata.sds;require;explicit;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mcdata.sds";require;explicit P-Preferred-Service: urn:urn-7:3gpp-service.ims.icsi.mcdata.sds Answer-Mode: Manual P-Preferred-Identity: sip:mcx.test-111.mcla@ims.mnc001.mcc001.3gppnetwork.org Session-Expires: 3600 Allow: INVITE, ACK, CANCEL, BYE, MESSAGE, OPTIONS, NOTIFY, PRACK, UPDATE, REFER Content-Type: multipart/mixed;boundary=6kVXJngsGPdsQ0qWtqXx41g5UScia9p4 Content-Length: 962

--6kVXJngsGPdsQ0qWtqXx41g5UScia9p4 Content-Type: application/resource-lists+xml Content-Length: 275

<?xml version="1.0" encoding="UTF-8"?>

--6kVXJngsGPdsQ0qWtqXx41g5UScia9p4 Content-Type: application/vnd.3gpp.mcdata-info+xml Content-Length: 143

one-to-one-sds

--6kVXJngsGPdsQ0qWtqXx41g5UScia9p4 Content-Type: application/vnd.3gpp.mcdata-signalling Content-Length: 39

2020-09-17 19:39:56.488640 *** message truncated at 1831 *** 2020-09-17 19:39:56.488715 tport.c:3047 tport_deliver() tport_deliver(0x556bff7416a0): msg 0x556bff761490 (2033 bytes) from udp/*.*.33.81:5060 next=(nil) 2020-09-17 19:39:56.488790 nta.c:3036 agent_recv_request() nta: received MESSAGE sip:mcptt-as-mcla-1.ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 (CSeq 58213) 2020-09-17 19:39:56.488877 nta.c:3253 agent_recv_request() nta: MESSAGE (58213) to message callback 2020-09-17 19:39:56.488971 processMessageStatelessly - incoming message with call-id c8oHzoxL8Lt.Prut0H9FJew9cduHCvvj does not match an existing call leg, processed in thread 140560800393600 2020-09-17 19:39:56.489058 ClientController::selectClientForRequestOutsideDialog - there are 1 possible clients, we are starting with offset 0 2020-09-17 19:39:56.489125 ClientController::route_request_outside_dialog - Selected client at offset 0 2020-09-17 19:39:56.489210 PendingRequestController::add - tport: 0x556bff7416a0, Call-ID: c8oHzoxL8Lt.Prut0H9FJew9cduHCvvj, transactionId 74de0050-e236-45af-829d-19845b155451 2020-09-17 19:39:56.489279 pending-request: Adding entry to go off in 64000ms 2020-09-17 19:39:56.489339 pending-request: Adding entry to the head (queue was empty), length: 1 2020-09-17 19:39:56.489434 ClientController::addNetTransaction: transactionId 74de0050-e236-45af-829d-19845b155451; size: 1 2020-09-17 19:39:56.489668 Client::write_handler - wrote 2191 bytes: system:0 2020-09-17 19:39:56.986599 tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x556bff7416a0): events IN 2020-09-17 19:39:56.986702 tport.c:2892 tport_recv_event() tport_recv_event(0x556bff7416a0) 2020-09-17 19:39:56.986750 tport.c:3229 tport_recv_iovec() tport_recv_iovec(0x556bff7416a0) msg 0x556bff75bb40 from (udp/*.*.46.7:5060) has 2033 bytes, veclen = 1 2020-09-17 19:39:56.986956 recv 2033 bytes from udp/[*.*.33.81]:57570 at 19:39:56.986791: MESSAGE sip:mcptt-as-mcla-1.ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 Via: SIP/2.0/UDP *.*.33.81:57570;rport;branch=z9hG4bKPjWyYL5ZsRwpSQXUd0U-HtHpAK9eIW4z7z Max-Forwards: 70 From: ;tag=dKAWd-RbsRFtqOFq2LhIvZylwU60PfvB To: Call-ID: c8oHzoxL8Lt.Prut0H9FJew9cduHCvvj CSeq: 58213 MESSAGE User-Agent: TEST e-TBS Contact: ;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mcptt";+g.3gpp.mcptt Accept-Contact: *;+g.3gpp.mcdata.sds;require;explicit;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mcdata.sds";require;explicit P-Preferred-Service: urn:urn-7:3gpp-service.ims.icsi.mcdata.sds Answer-Mode: Manual P-Preferred-Identity: Session-Expires: 3600 Allow: INVITE, ACK, CANCEL, BYE, MESSAGE, OPTIONS, NOTIFY, PRACK, UPDATE, REFER Content-Type: multipart/mixed;boundary=6kVXJngsGPdsQ0qWtqXx41g5UScia9p4 Content-Length: 962 --6kVXJngsGPdsQ0qWtqXx41g5UScia9p4 Content-Type: application/resource-lists+xml Content-Length: 275 --6kVXJngsGPdsQ0qWtqXx41g5UScia9p4 Content-Type: application/vnd.3gpp.mcdata-info+xml Content-Length: 143

one-to-one-sds

--6kVXJngsGPdsQ0qWtqXx41g5UScia9p4 Content-Type: application/vnd.3gpp.mcdata-signalling Content-Length: 39 2020-09-17 19:39:56.987037 *** message truncated at 1831 *** 2020-09-17 19:39:56.987072 tport.c:3047 tport_deliver() tport_deliver(0x556bff7416a0): msg 0x556bff75bb40 (2033 bytes) from udp/*.*.33.81:5060 next=(nil) 2020-09-17 19:39:56.987109 nta.c:3036 agent_recv_request() nta: received MESSAGE sip:mcptt-as-mcla-1.ims.mnc001.mcc001.3gppnetwork.org SIP/2.0 (CSeq 58213) 2020-09-17 19:39:56.987154 nta.c:3253 agent_recv_request() nta: MESSAGE (58213) to message callback 2020-09-17 19:39:56.987190 processMessageStatelessly - incoming message with call-id c8oHzoxL8Lt.Prut0H9FJew9cduHCvvj does not match an existing call leg, processed in thread 140560800393600

davehorton commented 3 years ago

I'm confused about this payload because the Content-Lengths don't look right given the content shown

Content-Type: multipart/mixed;boundary=6kVXJngsGPdsQ0qWtqXx41g5UScia9p4
Content-Length: 962

--6kVXJngsGPdsQ0qWtqXx41g5UScia9p4
Content-Type: application/resource-lists+xml
Content-Length: 275

--6kVXJngsGPdsQ0qWtqXx41g5UScia9p4
Content-Type: application/vnd.3gpp.mcdata-info+xml
Content-Length: 143

one-to-one-sds
--6kVXJngsGPdsQ0qWtqXx41g5UScia9p4
Content-Type: application/vnd.3gpp.mcdata-signalling
Content-Length: 39

If you can give me a text file with the exact message payload I could try to reproduce in my environment

p-akshay commented 3 years ago

Here is the Multipart content copied from Wireshark Packet

--evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/resource-lists+xml Content-Length: 275

<?xml version="1.0" encoding="UTF-8"?>

--evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/vnd.3gpp.mcdata-info+xml Content-Length: 143

one-to-one-sds

--evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/vnd.3gpp.mcdata-signalling Content-Length: 39

_c(B --evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE. Content-Type: application/vnd.3gpp.mcdata-payload Content-Length: 10

xTEST --evlTHXrwzdFmGLa1MjpDCNgk.5VyoxE.--

Just to add to this... the data received in 3rd content (39 Bytes) is encoded in a specific format... I am attaching part of the dump as well for better clarity

06c0 54 48 58 72 77 7a 64 46 6d 47 4c 61 31 4d 6a 70 THXrwzdFmGLa1Mjp 06d0 44 43 4e 67 6b 2e 35 56 79 6f 78 45 2e 0d 0a 43 DCNgk.5VyoxE...C 06e0 6f 6e 74 65 6e 74 2d 54 79 70 65 3a 20 61 70 70 ontent-Type: app 06f0 6c 69 63 61 74 69 6f 6e 2f 76 6e 64 2e 33 67 70 lication/vnd.3gp 0700 70 2e 6d 63 64 61 74 61 2d 73 69 67 6e 61 6c 6c p.mcdata-signall 0710 69 6e 67 0d 0a 43 6f 6e 74 65 6e 74 2d 4c 65 6e ing..Content-Len 0720 67 74 68 3a 20 20 20 20 33 39 0d 0a 0d 0a 01 00 gth: 39...... 0730 5f 63 28 42 00 00 00 00 00 00 00 00 00 00 00 00 _c(B............ 0740 00 00 00 05 00 00 00 00 00 00 00 00 00 00 00 00 ................ 0750 00 00 00 00 81 0d 0a 2d 2d 65 76 6c 54 48 58 72 .......--evlTHXr 0760 77 7a 64 46 6d 47 4c 61 31 4d 6a 70 44 43 4e 67 wzdFmGLa1MjpDCNg 0770 6b 2e 35 56 79 6f 78 45 2e 0d 0a 43 6f 6e 74 65 k.5VyoxE...Conte 0780 6e 74 2d 54 79 70 65 3a 20 61 70 70 6c 69 63 61 nt-Type: applica 0790 74 69 6f 6e 2f 76 6e 64 2e 33 67 70 70 2e 6d 63 tion/vnd.3gpp.mc 07a0 64 61 74 61 2d 70 61 79 6c 6f 61 64 0d 0a 43 6f data-payload..Co 07b0 6e 74 65 6e 74 2d 4c 65 6e 67 74 68 3a 20 20 20 ntent-Length:
07c0 20 31 30 0d 0a 0d 0a 03 01 78 00 05 01 54 45 53 10......x...TES 07d0 54 0d 0a 2d 2d 65 76 6c 54 48 58 72 77 7a 64 46 T..--evlTHXrwzdF 07e0 6d 47 4c 61 31 4d 6a 70 44 43 4e 67 6b 2e 35 56 mGLa1MjpDCNgk.5V 07f0 79 6f 78 45 2e 2d 2d 0d 0a yoxE.--..

davehorton commented 3 years ago

please send the wireshark pcap file

p-akshay commented 3 years ago

Hi @davehorton ,

I have shared the pcap file via email with you.

Thanks

p-akshay commented 3 years ago

Hi @davehorton ,

Just a few more updates on this...

The MIME content which is causing the issue is encoded in binary format and does have a "0" value present in it. My guess is this might be the root cause of problem.

Also after further analysis of logs, I can see that the received 2033 bytes are forwarded by "sofia" module.

2020-09-17 19:39:56.489668 Client::write_handler - wrote 2191 bytes: system:0

In normal case (when SIP Message is processed correctly), the write handler is followed by read handler e.g. 2020-09-21 10:21:38.766342 Client::write_handler - wrote 845 bytes: system:0 2020-09-21 10:21:38.778124 Client::read_handler read: 8bf1b8b0-2cba-4732-9234-31ca2cf1b5d7|sip|647e441d-5027-45c7-be19-5fa031665a43|

Let me know your analysis.

Thanks

davehorton commented 3 years ago

I think the issue is the binary payload in the multipart body of the message. A '0' value in that payload should not actually cause an issue, but I am not sure that it is being parsed correct wrt to the Content-Length. Have you got any means for me (ie code or working program) to generate an example sip MESSAGE request as shown in your example?

p-akshay commented 3 years ago

Hi @davehorton ,

Sorry for very late response on this issue...

we have worked on our client component and now are in a position to share the client with you for testing this in your environment ...

following is the sample javascript code that can be used with user agent like SIP.js to generate the binary message...in following case,

`function hex2a(hexx) { var hex = hexx.toString();//force conversion var str = ''; for (var i = 0; (i < hex.length && hex.substr(i, 2) !== '00'); i += 2){ str += String.fromCharCode(parseInt(hex.substr(i, 2), 16)); } return str; }

function sendMessage() { len = 0x05; time = Date.now(); time = time / 1000; // Convert it to seconds payload = hex2a(len ) + hex2a(time.toString(16)) + 'x';

session = user_agent.message('sip:abc@' + host, payload);

} ` Let me know if this helps

drachtio / drachtio-server

SIP MESSAGE event lost between Drachtio Server and Drachtio-srf #142