SIP Message events lost from drachtio server - Githubissues

drachtio / drachtio-server

A SIP call processing server that can be controlled via nodejs applications

https://drachtio.org

MIT License

233 stars 90 forks source link

SIP Message events lost from drachtio server #339

Open Vatsalsoni13 opened 5 months ago

Vatsalsoni13 commented 5 months ago

Overview:

User registers with drachtio server successfully, then generates a SIP Message which leads to the issue.

Expected messge:

MESSAGE example.org SIP/2.0
Via: SIP/2.0/WS 9m44aokjkv3e.invalid;branch=z9hG4bK1777670
To: <sip:example.org>
From: "xxxxxxxx" <sip:xxxxxx@xxxxxxxxxxxxxx>;tag=7vd4cmhrc6
CSeq: 1 MESSAGE
Call-ID: f10artt753csvbdh09bd
Max-Forwards: 70
Supported: outbound
User-Agent: SIP.js/0.21.2
Content-Type: application/vnd.3gpp.mcdata-signalling
Content-Length:38

eÉ¾³´¢IH©wÙÀ²ÞÉ 0DA@YÎµ¤U

This happens only in case of binary messages. Function used for binary conversion:

hex2a = (hexx: any) => {
    var hex = hexx.toString();//force conversion
    var str = '';
    for (var i = 0; (i < hex.length); i += 2) {
      str += String.fromCharCode(parseInt(hex.substr(i, 2), 16));
    }
    return str;
  }

Logs on drachtio server. Log-level - 9. udp-mtu set to 4096

2024-02-12 12:15:34.600846 tport.c:2845 tport_wakeup() tport_wakeup(0x559ab07bd730): events IN
2024-02-12 12:15:34.600969 tport.c:2949 tport_recv_event() tport_recv_event(0x559ab07bd730)
2024-02-12 12:15:34.601071 tport.c:3290 tport_recv_iovec() tport_recv_iovec(0x559ab07bd730) msg 0x559ab07f3b60 from (ws/192.x.x.x:50604) has 808 bytes, veclen = 1
2024-02-12 12:15:34.601339 recv 808 bytes from ws/[192.x.x.x]:50604 at 12:15:34.601128:
MESSAGE sip:example.org SIP/2.0
Via: SIP/2.0/WS 9m44aokjkv3e.invalid;branch=z9hG4bK1777670
To: <sip:example.org>
From: "xxxxxxxx" <sip:xxxxxx@xxxxxxxxxxxxxx>;tag=7vd4cmhrc6
CSeq: 1 MESSAGE
Call-ID: f10artt753csvbdh09bd
Max-Forwards: 70
Supported: outbound
User-Agent: SIP.js/0.21.2
Content-Type: application/vnd.3gpp.mcdata-signalling
Content-Length:38

   <ENCODED DATA>

2024-02-12 12:15:34.601413    *** message truncated at 585 ***
2024-02-12 12:15:34.601446 tport.c:3108 tport_deliver() tport_deliver(0x559ab07bd730): msg 0x559ab07f3b60 (808 bytes) from ws/192.x.x.x:50604 next=(nil)
2024-02-12 12:15:34.601477 tport.c:1181 tport_ref() tport_ref(0x559ab07bd730): refcount is now 2
2024-02-12 12:15:34.601512 nta.c:3060 agent_recv_request() nta: received MESSAGE sip:example.org SIP/2.0 (CSeq 1)
2024-02-12 12:15:34.601550 nta.c:3360 agent_check_request_via() nta: Via check: received=192.x.x.x
2024-02-12 12:15:34.601638 nta.c:3277 agent_recv_request() nta: MESSAGE (1) to message callback
2024-02-12 12:15:34.601670 processMessageStatelessly - incoming message with call-id f10artt753csvbdh09bd does not match an existing call leg, processed in thread 140615518198144
2024-02-12 12:15:34.601704 tport.c:1181 tport_ref() tport_ref(0x559ab07bd730): refcount is now 3
2024-02-12 12:15:34.601732 tport.c:1194 tport_unref() tport_unref(0x559ab07bd730): refcount is now 2
2024-02-12 12:15:34.601775 ClientController::selectClientForRequestOutsideDialog - there are 1 possible clients, we are starting with offset 0
2024-02-12 12:15:34.601808 ClientController::route_request_outside_dialog - Selected client at offset 0
2024-02-12 12:15:34.601838 tport.c:1181 tport_ref() tport_ref(0x559ab07bd730): refcount is now 3
2024-02-12 12:15:34.601866 tport.c:1194 tport_unref() tport_unref(0x559ab07bd730): refcount is now 2
2024-02-12 12:15:34.601911 tport.c:1181 tport_ref() tport_ref(0x559ab07bd730): refcount is now 3
2024-02-12 12:15:34.601938 PendingRequestController::add - tport: 0x559ab07bd730, Call-ID: f10artt753csvbdh09bd, transactionId f8043558-c5fb-44fa-a952-d7d70c3d1c6b
2024-02-12 12:15:34.601972 pending-request: Adding entry to go off in 64000ms
2024-02-12 12:15:34.601998 pending-request: Adding entry to the head (queue was empty), length: 1
2024-02-12 12:15:34.602047 tport.c:1181 tport_ref() tport_ref(0x559ab07bd730): refcount is now 4
2024-02-12 12:15:34.602082 tport.c:1194 tport_unref() tport_unref(0x559ab07bd730): refcount is now 3
2024-02-12 12:15:34.610146 tport.c:2845 tport_wakeup() tport_wakeup(0x559ab0751850): events IN
2024-02-12 12:15:34.610241 tport.c:2949 tport_recv_event() tport_recv_event(0x559ab0751850)
2024-02-12 12:15:34.610318 tport.c:3290 tport_recv_iovec() tport_recv_iovec(0x559ab0751850) msg 0x559ab076a490 from (tcp/192.x.x.x:8642) has 504 bytes, veclen = 1
2024-02-12 12:15:34.610580 recv 504 bytes from tcp/[192.x.x.x]:8642 at 12:15:34.610392:
SIP/2.0 403 Forbidden
Via: SIP/2.0/TCP 192.x.x.x:9357;branch=z9hG4bKytD18FeBUHa5B;rport=38855
From: "xxxxxxxx" <sip:xxxxxx@xxxxxxxxxxxxxx>;tag=7vd4cmhrc6
To: <sip:example.org>;tag=e6SNrypZQBFDg
Call-ID: 2a12c9ec-4415-123d-ccb2-80e82c5694de
CSeq: 79306375 MESSAGE
User-Agent: xxxxxxxxxxx
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: path, replaces
Content-Length: 0

2024-02-12 12:15:34.610719 tport.c:3108 tport_deliver() tport_deliver(0x559ab0751850): msg 0x559ab076a490 (504 bytes) from tcp/192.x.x.x:8642 next=(nil)
2024-02-12 12:15:34.610769 tport.c:1181 tport_ref() tport_ref(0x559ab0751850): refcount is now 10
2024-02-12 12:15:34.610803 nta.c:3484 agent_recv_response() nta: received 403 Forbidden for MESSAGE (79306375)
2024-02-12 12:15:34.610836 nta.c:3551 agent_recv_response() nta: 403 Forbidden is going to a transaction
2024-02-12 12:15:34.610871 nta.c:9813 outgoing_estimate_delay() nta_outgoing: RTT is 2.363 ms
2024-02-12 12:15:34.610909 nta.c:9596 outgoing_recv() outgoing_recv: tport(0x559ab0751850) orq(0x559ab070f670) calling tport_release because we have pending 4
2024-02-12 12:15:34.610958 tport.c:4319 tport_release() tport_release(0x559ab0751850): 0x559ab07850e0 by 0x559ab070f670 with 0x559ab076a490
2024-02-12 12:15:34.610999 SipDialogController::processResponseOutsideDialog
2024-02-12 12:15:34.611043 tport.c:1181 tport_ref() tport_ref(0x559ab0751850): refcount is now 11
2024-02-12 12:15:34.611095 tport.c:1194 tport_unref() tport_unref(0x559ab0751850): refcount is now 10
2024-02-12 12:15:34.611133 SipDialogController::findRIPByOrq orq 0x559ab070f670
2024-02-12 12:15:34.611172 SipDialogController::clearRIP clearing orq 0x559ab070f670
2024-02-12 12:15:34.611211 nta.c:8953 outgoing_free() nta: outgoing_free(0x559ab070f670)
2024-02-12 12:15:34.611250 tport.c:1194 tport_unref() tport_unref(0x559ab0751850): refcount is now 9
2024-02-12 12:15:34.611359 ClientController::removeAppTransaction: transactionId 1d19b4dd-d120-42e4-9fd3-0d748607dc73; size: 0
2024-02-12 12:15:34.611451 tport.c:1194 tport_unref() tport_unref(0x559ab0751850): refcount is now 8
2024-02-12 12:15:34.611520 tport.c:2363 tport_set_secondary_timer() tport(0x559ab0751850): reset timer
2024-02-12 12:15:34.611544 Client::write_handler - wrote 639 bytes: system:0