search

drachtio / drachtio-server

A SIP call processing server that can be controlled via nodejs applications
https://drachtio.org
MIT License
237 stars 92 forks source link

Websocket Headers case sensitive #160

Open danjenkins opened 3 years ago

danjenkins commented 3 years ago

I've just tried to front Drachtio with haproxy... which by default converts all the proxied headers to lowercase and Drachtio replies with a 400 Bad Request with the proxied websocket. Once I sent non converted headers, drachtio was fine with the proxied websocket.

In theory haproxy was doing nothing wrong because http headers are case insensitive. Does Drachtio expect headers to come in as Pascal-Case? It seems like the header in particular that causes the issue is Sec-WebSocket-Key that once you make any of it lowercase Drachtio-Server replies with a 400 bad request - i.e sec-WebSocket-Key causes the 400 Bad Request - It appears Sec-WebSocket-Protocol also needs to be Pascal-Case too

davehorton commented 3 years ago

can you share the drachtio server log showing the INVITE and the 400 response?

danjenkins commented 3 years ago

Applicable log portion attached below

drachtio_1         | 2021-06-23 14:41:19.166734 Starting sofia event loop in main thread: 140461755475264
drachtio_1         | 2021-06-23 14:41:28.850864 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x561f72437480): events IN
drachtio_1         | 2021-06-23 14:41:28.851460 tport.c:880 tport_alloc_secondary() tport_alloc_secondary(0x561f72437480): new secondary tport 0x7fbfcc07c010
drachtio_1         | 2021-06-23 14:41:28.852183 tport.c:2648 tport_accept() tport_accept(0x561f72437480): incoming secondary on ws/192.168.64.4:8000 failed. reason = WS_INIT
drachtio_1         | 2021-06-23 14:41:34.393325 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x561f72437480): events IN
drachtio_1         | 2021-06-23 14:41:34.393507 tport.c:880 tport_alloc_secondary() tport_alloc_secondary(0x561f72437480): new secondary tport 0x561f7243c090
drachtio_1         | 2021-06-23 14:41:34.393670 tport.c:2648 tport_accept() tport_accept(0x561f72437480): incoming secondary on ws/192.168.64.4:8000 failed. reason = WS_INIT

Just to be clear - we're not even getting to the INVITE/REGISTER/Whatever... this is purely connecting a websocket to drachtio via haproxy

davehorton commented 3 years ago

can you turn sofia-loglevel to 9, redo the test and share the complete log

danjenkins commented 3 years ago

Full log on level 9 sofia, debug log level for drachtio-server

drachtio_1         | 2021-06-23 14:41:19.056919 Starting drachtio version v0.8.9-rc2-3-gfb3deb3c6
drachtio_1         | 2021-06-23 14:41:19.057028 Logging threshold:                     5
drachtio_1         | 2021-06-23 14:41:19.057114 Route for outbound connection:         sip-method: *, http-method: POST, http-url: http://url.com/foo
drachtio_1         | 2021-06-23 14:41:19.057196 DrachtioController::run: Main thread id: 140461755475264
drachtio_1         | 2021-06-23 14:41:19.057354 DrachtioController::run listening for applications on tcp port 9022 only
drachtio_1         | 2021-06-23 14:41:19.062772 ClientController::ClientController done setting tls options:
drachtio_1         | 2021-06-23 14:41:19.062856 Client controller initializing with tcp only
drachtio_1         | 2021-06-23 14:41:19.063719 Client controller thread id: 140461755475264
drachtio_1         | 2021-06-23 14:41:19.065063 ClientController::start_accept_tcp
drachtio_1         | 2021-06-23 14:41:19.065254 DrachtioController::run mtu size for udp packets: 4096
drachtio_1         | 2021-06-23 14:41:19.065241 Client controller thread id: 140461755459328
drachtio_1         | 2021-06-23 14:41:19.065443 ClientController::threadFunc - ClientController: io_context run loop started (or restarted)
drachtio_1         | 2021-06-23 14:41:19.065308 DrachtioController::run - sipcapture/Homer enabled: udp:10.155.250.80:9060;hep=3;capture_id=191
drachtio_1         | 2021-06-23 14:41:19.067755 responding to Prometheus on 0.0.0.0:8088
drachtio_1         | 2021-06-23 14:41:19.069035 tcp keep alives will be sent to clients every 45 seconds
drachtio_1         | 2021-06-23 14:41:19.073060 DrachtioController::run: starting sip stack on sip:*:5060;transport=udp,tcp
drachtio_1         | 2021-06-23 14:41:19.073123 SipTransport::getBindableContactUri: sip:*:5060;transport=udp,tcp
drachtio_1         | 2021-06-23 14:41:19.073311 nta.c:968 nta_agent_create() nta_agent_create: initialized hash tables
drachtio_1         | 2021-06-23 14:41:19.073395 tport.c:516 tport_tcreate() tport_create(): 0x561f72431c70
drachtio_1         | 2021-06-23 14:41:19.085266 tport_logging.c:204 tport_open_log() events HEP RRR DATA [hep=3;capture_id=191]
drachtio_1         | 2021-06-23 14:41:19.085382 tport_logging.c:204 tport_open_log() events HEP RRR DATA [capture_id=191]
drachtio_1         | 2021-06-23 14:41:19.085694 nta.c:2382 agent_create_master_transport() nta: master transport created
drachtio_1         | 2021-06-23 14:41:19.085957 tport.c:1643 tport_bind_server() tport_bind_server(0x561f72431c70) to */*:5060
drachtio_1         | 2021-06-23 14:41:19.087162 tport.c:1713 tport_bind_server() tport_bind_server(0x561f72431c70): calling tport_listen for udp
drachtio_1         | 2021-06-23 14:41:19.087352 tport.c:639 tport_alloc_primary() tport_alloc_primary(0x561f72431c70): new primary tport 0x561f724325e0
drachtio_1         | 2021-06-23 14:41:19.087685 tport.c:769 tport_listen() tport_listen(0x561f724325e0): listening at udp/192.168.64.4:5060
drachtio_1         | 2021-06-23 14:41:19.087816 tport.c:1713 tport_bind_server() tport_bind_server(0x561f72431c70): calling tport_listen for tcp
drachtio_1         | 2021-06-23 14:41:19.087898 tport.c:639 tport_alloc_primary() tport_alloc_primary(0x561f72431c70): new primary tport 0x561f72432ac0
drachtio_1         | 2021-06-23 14:41:19.088121 tport.c:769 tport_listen() tport_listen(0x561f72432ac0): listening at tcp/192.168.64.4:5060
drachtio_1         | 2021-06-23 14:41:19.088243 tport.c:1713 tport_bind_server() tport_bind_server(0x561f72431c70): calling tport_listen for udp
drachtio_1         | 2021-06-23 14:41:19.088324 tport.c:639 tport_alloc_primary() tport_alloc_primary(0x561f72431c70): new primary tport 0x561f724333c0
drachtio_1         | 2021-06-23 14:41:19.088617 tport.c:769 tport_listen() tport_listen(0x561f724333c0): listening at udp/127.0.0.1:5060
drachtio_1         | 2021-06-23 14:41:19.088712 tport.c:1713 tport_bind_server() tport_bind_server(0x561f72431c70): calling tport_listen for tcp
drachtio_1         | 2021-06-23 14:41:19.088894 tport.c:639 tport_alloc_primary() tport_alloc_primary(0x561f72431c70): new primary tport 0x561f72433870
drachtio_1         | 2021-06-23 14:41:19.089022 tport.c:769 tport_listen() tport_listen(0x561f72433870): listening at tcp/127.0.0.1:5060
drachtio_1         | 2021-06-23 14:41:19.089188 nta.c:2341 nta_agent_add_tport() nta: bound to (*:5060;transport=*)
drachtio_1         | 2021-06-23 14:41:19.089294 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/udp 192.168.64.4 (*)
drachtio_1         | 2021-06-23 14:41:19.089471 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 192.168.64.4 (*)
drachtio_1         | 2021-06-23 14:41:19.089579 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/udp 127.0.0.1 (*)
drachtio_1         | 2021-06-23 14:41:19.089656 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 127.0.0.1 (*)
drachtio_1         | 2021-06-23 14:41:19.089844 nta.c:2350 nta_agent_add_tport() nta: Via fields initialized
drachtio_1         | 2021-06-23 14:41:19.090079 nta.c:2358 nta_agent_add_tport() nta: Contact header created
drachtio_1         | 2021-06-23 14:41:19.090267 nta.c:975 nta_agent_create() nta_agent_create: initialized transports
drachtio_1         | 2021-06-23 14:41:19.090353 nta.c:981 nta_agent_create() nta_agent_create: initialized random identifiers
drachtio_1         | 2021-06-23 14:41:19.090518 nta.c:987 nta_agent_create() nta_agent_create: initialized timer
drachtio_1         | 2021-06-23 14:41:19.090718 sres.c:2464 sres_parse_options() sres: /etc/resolv.conf: unknown option
drachtio_1         | 2021-06-23 14:41:19.090904 nta.c:997 nta_agent_create() nta_agent_create: initialized resolver
drachtio_1         | 2021-06-23 14:41:19.101932 SipTransport::addTransports - creating transport: 0x561f724325e0: udp/192.168.64.4:5060
drachtio_1         | 2021-06-23 14:41:19.107049 SipTransport::addTransports - creating transport: 0x561f72432ac0: tcp/192.168.64.4:5060
drachtio_1         | 2021-06-23 14:41:19.108930 SipTransport::addTransports - creating transport: 0x561f724333c0: udp/127.0.0.1:5060
drachtio_1         | 2021-06-23 14:41:19.115437 SipTransport::addTransports - creating transport: 0x561f72433870: tcp/127.0.0.1:5060
drachtio_1         | 2021-06-23 14:41:19.127193 DrachtioController::run: adding additional internal sip address sip:*:8000;transport=ws (external address: 10.155.250.191)
drachtio_1         | 2021-06-23 14:41:19.137381 SipTransport::getBindableContactUri: sip:10.155.250.191:8000;transport=ws;maddr=*
drachtio_1         | 2021-06-23 14:41:19.137542 tport.c:1643 tport_bind_server() tport_bind_server(0x561f72431c70) to ws/*:8000
drachtio_1         | 2021-06-23 14:41:19.137779 tport.c:1713 tport_bind_server() tport_bind_server(0x561f72431c70): calling tport_listen for ws
drachtio_1         | 2021-06-23 14:41:19.137870 tport.c:639 tport_alloc_primary() tport_alloc_primary(0x561f72431c70): new primary tport 0x561f72437480
drachtio_1         | 2021-06-23 14:41:19.138059 tport.c:769 tport_listen() tport_listen(0x561f72437480): listening at ws/192.168.64.4:8000
drachtio_1         | 2021-06-23 14:41:19.138142 tport.c:1713 tport_bind_server() tport_bind_server(0x561f72431c70): calling tport_listen for ws
drachtio_1         | 2021-06-23 14:41:19.138249 tport.c:639 tport_alloc_primary() tport_alloc_primary(0x561f72431c70): new primary tport 0x561f72437940
drachtio_1         | 2021-06-23 14:41:19.138359 tport.c:769 tport_listen() tport_listen(0x561f72437940): listening at ws/127.0.0.1:8000
drachtio_1         | 2021-06-23 14:41:19.138475 nta.c:2341 nta_agent_add_tport() nta: bound to (10.155.250.191:8000;transport=ws;maddr=*)
drachtio_1         | 2021-06-23 14:41:19.138572 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/udp 192.168.64.4 (*)
drachtio_1         | 2021-06-23 14:41:19.138678 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 192.168.64.4 (*)
drachtio_1         | 2021-06-23 14:41:19.138764 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/udp 127.0.0.1 (*)
drachtio_1         | 2021-06-23 14:41:19.138849 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/tcp 127.0.0.1 (*)
drachtio_1         | 2021-06-23 14:41:19.138955 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/ws 10.155.250.191:8000 (*)
drachtio_1         | 2021-06-23 14:41:19.139043 nta.c:2484 agent_init_via() nta: agent_init_via: SIP/2.0/ws 10.155.250.191:8000 (*)
drachtio_1         | 2021-06-23 14:41:19.139241 nta.c:2350 nta_agent_add_tport() nta: Via fields initialized
drachtio_1         | 2021-06-23 14:41:19.139436 nta.c:2358 nta_agent_add_tport() nta: Contact header created
drachtio_1         | 2021-06-23 14:41:19.152072 SipTransport::addTransports - creating transport: 0x561f72437480: ws/192.168.64.4:8000
drachtio_1         | 2021-06-23 14:41:19.158797 SipTransport::addTransports - creating transport: 0x561f72437940: ws/127.0.0.1:8000
drachtio_1         | 2021-06-23 14:41:19.165661 SipTransport::logTransports - there are : 6 transports
drachtio_1         | 2021-06-23 14:41:19.165765 SipTransport::logTransports - ws/127.0.0.1:8000 (sip:*:8000;transport=ws, external-ip: 10.155.250.191, local-net: 10.0.0.0/8)
drachtio_1         | 2021-06-23 14:41:19.165992 SipTransport::logTransports - tcp/127.0.0.1:5060 (sip:*:5060;transport=udp,tcp, external-ip: , local-net: 127.0.0.1/32)
drachtio_1         | 2021-06-23 14:41:19.166138 SipTransport::logTransports - ws/192.168.64.4:8000 (sip:*:8000;transport=ws, external-ip: 10.155.250.191, local-net: 10.0.0.0/8)
drachtio_1         | 2021-06-23 14:41:19.166238 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
drachtio_1         | 2021-06-23 14:41:19.166316 SipTransport::logTransports - udp/192.168.64.4:5060 (sip:*:5060;transport=udp,tcp, external-ip: , local-net: ), mtu size: 4096
drachtio_1         | 2021-06-23 14:41:19.166439 SipTransport::logTransports - tcp/192.168.64.4:5060 (sip:*:5060;transport=udp,tcp, external-ip: , local-net: )
drachtio_1         | 2021-06-23 14:41:19.166610 DrachtioController::run - sip timers: T1: 500ms, T2: 4000ms, T4: 5000ms, T1X64: 32000ms
drachtio_1         | 2021-06-23 14:41:19.166734 Starting sofia event loop in main thread: 140461755475264
drachtio_1         | 2021-06-23 14:41:28.850864 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x561f72437480): events IN
drachtio_1         | 2021-06-23 14:41:28.851460 tport.c:880 tport_alloc_secondary() tport_alloc_secondary(0x561f72437480): new secondary tport 0x7fbfcc07c010
drachtio_1         | 2021-06-23 14:41:28.852183 tport.c:2648 tport_accept() tport_accept(0x561f72437480): incoming secondary on ws/192.168.64.4:8000 failed. reason = WS_INIT
drachtio_1         | 2021-06-23 14:41:34.393325 tport.c:2777 tport_wakeup_pri() tport_wakeup_pri(0x561f72437480): events IN
drachtio_1         | 2021-06-23 14:41:34.393507 tport.c:880 tport_alloc_secondary() tport_alloc_secondary(0x561f72437480): new secondary tport 0x561f7243c090
drachtio_1         | 2021-06-23 14:41:34.393670 tport.c:2648 tport_accept() tport_accept(0x561f72437480): incoming secondary on ws/192.168.64.4:8000 failed. reason = WS_INIT
davehorton commented 3 years ago

ok, sorry my bad -- you are talking about HTTP(S) headers on the initial http connection that gets upgraded to a websocket. Will look into this

danjenkins commented 3 years ago

No worries! Thank you!

davehorton commented 3 years ago

can you help give me some easy way to recreate this? I'm going to have to set up a system to recreate so I can step through the code in the debugger, as it seems like the code should be handling this