search

drachtio / drachtio-siprec-recording-server

SIPREC recording server based on drachtio and rtpengine
MIT License
81 stars 31 forks source link

client sent invalid message -- JSON message length not specified properly #47

Closed dvillaume closed 2 years ago

dvillaume commented 3 years ago

Hi,

We tried to use Drachtio with a Broadworks platform using SIPREC. Here is the SIPREC content sent by Broadworks:

INVITE sip:172.16.33.210:9023;transport=tcp SIP/2.0 Via:SIP/2.0/TCP 172.19.0.11;branch=z9hG4bKBroadWorks.-112vbje-172.16.33.210V9023-0-82196506-923010692-1623662030899- From:"CallingLineIdFirstName CallingLineIdLastName"sip:12345@99.abc;tag=923010692-1623662030899- To: Call-ID:BW1113508991406211790462808@172.19.0.11 CSeq:82196506 INVITE Contact:<sip:172.19.0.11:5060;transport=tcp>;src Privacy:none Recv-Info: X-BroadWorks-Correlation-Info:2f420dae-06ac-4ac0-8ee6-f23d959a9d7e Accept:application/media_control+xml,application/sdp,application/x-broadworks-call-center+xml Allow:ACK,BYE,CANCEL,INFO,INVITE,OPTIONS,PRACK,REFER,NOTIFY Supported: Max-Forwards:60 Content-Type:multipart/mixed;boundary=UniqueBroadWorksBoundary Content-Length:2475 MIME-Version:1.0

--UniqueBroadWorksBoundary Content-Type:application/rs-metadata+xml Content-Disposition:recording-session Content-Length:1964

<?xml version="1.0" encoding="UTF-8"?>completeSRCselectiveinitiator>sip:12345@99.abc</initiator2021-06-14T11:13:50+02:00aor>sip:12345@99.abc</aorurn:uuid:50decb38-89a5-468e-8e0d-9e78301618c2aor>sip:+33987654321@99.abc;user=phone</aorurn:uuid:50decb38-89a5-468e-8e0d-9e78301618c2mixedextTrackingID>2f420dae-06ac-4ac0-8ee6-f23d959a9d7e</extTrackingID><serviceProviderID>22</serviceProviderID><groupID>555</groupID><userID>12345@99.abc</userIDcallID>callhalf-316217:0</callID><callType><origCall><callingPartyNumber>sip:+33123456789@99.abc</callingPartyNumbercalledPartyNumber>sip:+33987654321@99.abc;user=phone</calledPartyNumberdialedDigits>sip:+33987654321@99.abc</dialedDigitson --UniqueBroadWorksBoundary Content-Type:application/sdp Content-Length:263

v=0 o=BroadWorks 68 1 IN IP4 172.19.0.11 s=- c=IN IP4 172.19.0.14 t=0 0 m=audio 10906 RTP/AVP 8 9 0 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendonly a=label:1

--UniqueBroadWorksBoundary--

Drachtio answers this:

drachtio | 2021-06-14 09:13:50.906253 ClientController::accept_handler_tcp - got connection drachtio | 2021-06-14 09:13:50.906449 Client::start - Received connection from client at 172.32.0.1:38490 drachtio | 2021-06-14 09:13:50.906545 ClientController::join - Added client, count of connected clients is now: 1 drachtio | 2021-06-14 09:13:50.906649 ClientController::start_accept_tcp drachtio | 2021-06-14 09:13:50.907251 Client::read_handler client sent invalid message -- JSON message length not specified properly drachtio | 2021-06-14 09:13:50.907334 ClientController::leave - Removed client, count of connected clients is now: 0 drachtio | 2021-06-14 09:13:50.907474 BaseClient::~BaseClient

We didn't find any reason or documentation explaining why this "JSON message length not specified properly" error occurs.

Replaces https://github.com/drachtio/drachtio-server/issues/159 that was created under wrong repo.

Can you help us to why this error happens and how to fix it please ?

Regards, David

davehorton commented 3 years ago

This is complaining about the message sent from the drachtio app back to the drachtio server. Could you run the siprec-recording app with DEBUG=drachtio:agent and collect the logs generated from the app and post here?

dvillaume commented 2 years ago

Hello, i did try to launch the docker with following env : "DRACHTIO_DEBUG=drachtio:agent" and "DEBUG=drachtio:agent" but cannot grab more logs.

Can i launch this debug in docker mode or should i manually buil and export vars in app ?

Regards, David.

davehorton commented 2 years ago

DEBUG=drachtio:agent is the setting you want, are you sure you are properly setting this env var in the container when you launch the drachtio app?

dvillaume commented 2 years ago

I checked twice and even inside container 

root@6a375c27ff21:/# env | grep DEBUG
DEBUG=drachtio:agent

but i can't gather more logs than :

drachtio | 2021-08-30 13:03:22.754960 Starting drachtio version v0.8.9-rc2-3-gfb3deb3c6 drachtio | 2021-08-30 13:03:22.755252 Logging threshold: 5 drachtio | 2021-08-30 13:03:22.755340 DrachtioController::run: Main thread id: 139857678640448 drachtio | 2021-08-30 13:03:22.755431 DrachtioController::run listening for applications on tcp port 9022 and tls port 0 drachtio | 2021-08-30 13:03:22.760299 ClientController::ClientController done setting tls options: drachtio | 2021-08-30 13:03:22.760492 Client controller thread id: 139857678640448 drachtio | 2021-08-30 13:03:22.761945 ClientController::start_accept_tcp drachtio | 2021-08-30 13:03:22.762171 Client controller thread id: 139857678624512 drachtio | 2021-08-30 13:03:22.762264 Prometheus support disabled drachtio | 2021-08-30 13:03:22.762280 ClientController::threadFunc - ClientController: io_context run loop started (or restarted) drachtio | 2021-08-30 13:03:22.762361 tcp keep alives will be sent to clients every 45 seconds drachtio | 2021-08-30 13:03:22.762619 DrachtioController::run: starting sip stack on sip:*;transport=udp drachtio | 2021-08-30 13:03:22.762701 SipTransport::getBindableContactUri: sip:*;transport=udp drachtio | 2021-08-30 13:03:22.762890 nta.c:968 nta_agent_create() nta_agent_create: initialized hash tables drachtio | 2021-08-30 13:03:22.763041 tport.c:516 tport_tcreate() tport_create(): 0x5586f72f2e30 drachtio | 2021-08-30 13:03:22.763152 nta.c:2382 agent_create_master_transport() nta: master transport created drachtio | 2021-08-30 13:03:22.763903 tport.c:1643 tport_bind_server() tport_bind_server(0x5586f72f2e30) to udp/*:5060 drachtio | 2021-08-30 13:03:22.764674 tport.c:1713 tport_bind_server() tport_bind_server(0x5586f72f2e30): calling tport_listen for udp drachtio | 2021-08-30 13:03:22.764772 tport.c:639 tport_alloc_primary() tport_alloc_primary(0x5586f72f2e30): new primary tport 0x5586f72f3840 drachtio | 2021-08-30 13:03:22.765104 tport.c:769 tport_listen() tport_listen(0x5586f72f3840): listening at udp/172.32.0.2:5060 drachtio | 2021-08-30 13:03:22.765180 tport.c:1713 tport_bind_server() tport_bind_server(0x5586f72f2e30): calling tport_listen for udp drachtio | 2021-08-30 13:03:22.765328 tport.c:639 tport_alloc_primary() tport_alloc_primary(0x5586f72f2e30): new primary tport 0x5586f72f3d20 drachtio | 2021-08-30 13:03:22.765496 tport.c:769 tport_listen() tport_listen(0x5586f72f3d20): listening at udp/127.0.0.1:5060 drachtio | 2021-08-30 13:03:22.765569 tport.c:1713 tport_bind_server() tport_bind_server(0x5586f72f2e30): calling tport_listen for udp drachtio | 2021-08-30 13:03:22.765633 tport.c:639 tport_alloc_primary() tport_alloc_primary(0x5586f72f2e30): new primary tport 0x5586f72f4220 drachtio | 2021-08-30 13:03:22.765843 tport.c:769 tport_listen() tport_listen(0x5586f72f4220): listening at udp/[::1]:5060 drachtio | 2021-08-30 13:03:22.765919 nta.c:2341 nta_agent_add_tport() nta: bound to (*:5060;transport=udp) drachtio | 2021-08-30 13:03:22.765999 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/udp 172.32.0.2 (*) drachtio | 2021-08-30 13:03:22.766117 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/udp 127.0.0.1 (*) drachtio | 2021-08-30 13:03:22.766197 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/udp [::1] (*) drachtio | 2021-08-30 13:03:22.766310 nta.c:2350 nta_agent_add_tport() nta: Via fields initialized drachtio | 2021-08-30 13:03:22.766480 nta.c:2358 nta_agent_add_tport() nta: Contact header created drachtio | 2021-08-30 13:03:22.766538 nta.c:975 nta_agent_create() nta_agent_create: initialized transports drachtio | 2021-08-30 13:03:22.766589 nta.c:981 nta_agent_create() nta_agent_create: initialized random identifiers drachtio | 2021-08-30 13:03:22.766629 nta.c:987 nta_agent_create() nta_agent_create: initialized timer drachtio | 2021-08-30 13:03:22.766790 nta.c:997 nta_agent_create() nta_agent_create: initialized resolver drachtio | 2021-08-30 13:03:22.768955 SipTransport::addTransports - creating transport: 0x5586f72f3840: udp/172.32.0.2:5060 drachtio | 2021-08-30 13:03:22.772089 SipTransport::addTransports - creating transport: 0x5586f72f3d20: udp/127.0.0.1:5060 drachtio | 2021-08-30 13:03:22.775093 SipTransport::addTransports - creating transport: 0x5586f72f4220: udp/[::1]:5060 drachtio | 2021-08-30 13:03:22.777388 SipTransport::logTransports - there are : 3 transports drachtio | 2021-08-30 13:03:22.777491 SipTransport::logTransports - udp/[::1]:5060 (sip:*;transport=udp, external-ip: , local-net: ), mtu size: 1300 drachtio | 2021-08-30 13:03:22.777541 SipTransport::logTransports - udp/172.32.0.2:5060 (sip:*;transport=udp, external-ip: , local-net: ), mtu size: 1300 drachtio | 2021-08-30 13:03:22.777576 SipTransport::logTransports - udp/127.0.0.1:5060 (sip:*;transport=udp, external-ip: , local-net: 127.0.0.1/32), mtu size: 1300 drachtio | 2021-08-30 13:03:22.777743 DrachtioController::run - sip timers: T1: 500ms, T2: 4000ms, T4: 5000ms, T1X64: 32000ms drachtio | 2021-08-30 13:03:22.777824 Starting sofia event loop in main thread: 139857678640448 drachtio | 2021-08-30 13:03:34.849853 ClientController::accept_handler_tcp - got connection drachtio | 2021-08-30 13:03:34.850106 Client::start - Received connection from client at 172.32.0.1:59010 drachtio | 2021-08-30 13:03:34.850216 ClientController::join - Added client, count of connected clients is now: 1 drachtio | 2021-08-30 13:03:34.850348 ClientController::start_accept_tcp drachtio | 2021-08-30 13:03:34.852703 Client::read_handler client sent invalid message -- JSON message length not specified properly drachtio | 2021-08-30 13:03:34.852831 ClientController::leave - Removed client, count of connected clients is now: 0 drachtio | 2021-08-30 13:03:34.852999 BaseClient::~BaseClient

davehorton commented 2 years ago

you've added the env var to the wrong container -- it needs to be added to the container in which you are running the drachtio siprec app

dvillaume commented 2 years ago

Hello, The error was on our side as we misunderstood the relationship between the app and drachtio. Now we notice that the behavour of broadworks is the same as in https://github.com/drachtio/drachtio-siprec-recording-server/issues/8

I closed this ticket, thanks for your help.