2024-09-04T09:45:59.026747867Z 21(617) INFO: <core> [core/cfg/cfg_ctx.c:589]: cfg_set_now(): core.debug has been changed to 3
2024-09-04T09:45:59.026778233Z 21(617) DEBUG: ctl [io_listener.c:520]: handle_stream_read(): bytes processed: 23
2024-09-04T09:45:59.027102562Z 21(617) DEBUG: ctl [io_listener.c:496]: handle_stream_read(): handle_stream read: eof on /var/run/kamailio/kamailio_ctl
2024-09-04T09:45:59.027113963Z 21(617) DEBUG: ctl [../../core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x7f71ec36e380, 14, -1, 0x10) fd_no=2 called
2024-09-04T09:46:07.751372012Z 46(642) DEBUG: <core> [core/ip_addr.c:577]: print_ip(): tcpconn_new: new tcp connection: 11.15.32.1
2024-09-04T09:46:07.751410558Z 46(642) DEBUG: <core> [core/tcp_main.c:1242]: tcpconn_new(): on port 33333, type 2, socket 121
2024-09-04T09:46:07.751419230Z 46(642) DEBUG: <core> [core/tcp_main.c:1633]: tcpconn_add(): hashes: 3253:271:351, 1
2024-09-04T09:46:07.751426024Z 46(642) DEBUG: <core> [core/io_wait.h:369]: io_watch_add(): processing io_watch_add(0x55dda96c6da0, 121, 2, 0x7f71ed7f52d0) - fd_no=71
2024-09-04T09:46:07.751445604Z 46(642) DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x55dda96c6da0, 121, -1, 0x0) fd_no=72 called
2024-09-04T09:46:07.751450837Z 46(642) DEBUG: <core> [core/tcp_main.c:4684]: handle_tcpconn_ev(): sending to child, events 1
2024-09-04T09:46:07.751455114Z 46(642) DEBUG: <core> [core/tcp_main.c:4328]: send2child(): checking per-socket generic workers (627/31..639/43) [tcp:198.18.55.66:80]
2024-09-04T09:46:07.751459615Z 46(642) DEBUG: <core> [core/tcp_main.c:4359]: send2child(): selected tcp worker idx:0 proc:31 pid:627 for activity on [tcp:198.18.55.66:80], 0x7f71ed7f52d0
2024-09-04T09:46:07.751561536Z 31(627) DEBUG: <core> [core/tcp_read.c:1776]: handle_io(): received n=8 con=0x7f71ed7f52d0, fd=14
2024-09-04T09:46:07.751570310Z 31(627) DEBUG: <core> [core/io_wait.h:369]: io_watch_add(): processing io_watch_add(0x55dda9722f40, 14, 2, 0x7f71ed7f52d0) - fd_no=1
2024-09-04T09:46:07.752908363Z 31(627) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 1 (request) flags 2
2024-09-04T09:46:07.753041229Z 31(627) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 1 (request) flags 2
2024-09-04T09:46:07.753053348Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:721]: parse_msg(): SIP Request:
2024-09-04T09:46:07.753058474Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:723]: parse_msg():  method:  <GET>
2024-09-04T09:46:07.753062351Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:725]: parse_msg():  uri:     </>
2024-09-04T09:46:07.753066472Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:727]: parse_msg():  version: <HTTP/1.1>
2024-09-04T09:46:07.753070532Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Special] type 0
2024-09-04T09:46:07.753075142Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.753079735Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.753299417Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.753308638Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.753732049Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Extensions] type 0
2024-09-04T09:46:07.753806513Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.753812678Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.753817052Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
2024-09-04T09:46:07.753831965Z 31(627) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 1 (request) flags 2
2024-09-04T09:46:07.753836385Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:721]: parse_msg(): SIP Request:
2024-09-04T09:46:07.753840368Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:723]: parse_msg():  method:  <GET>
2024-09-04T09:46:07.753844202Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:725]: parse_msg():  uri:     </>
2024-09-04T09:46:07.753848173Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:727]: parse_msg():  version: <HTTP/1.1>
2024-09-04T09:46:07.753856353Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Special] type 0
2024-09-04T09:46:07.753860923Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.753864897Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.753868757Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.753872226Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.753876161Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Extensions] type 0
2024-09-04T09:46:07.753879796Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.753883526Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.753887370Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
2024-09-04T09:46:07.753892044Z 31(627) DEBUG: <core> [core/receive.c:392]: receive_msg(): --- received sip message - request - call-id: [] - cseq: []
2024-09-04T09:46:07.753896575Z 31(627) DEBUG: <core> [core/receive.c:263]: ksr_evrt_pre_routing(): event route core:pre-routing not defined
2024-09-04T09:46:07.753900251Z 31(627) DEBUG: <core> [core/receive.c:429]: receive_msg(): handling non-sip request message
2024-09-04T09:46:07.753904128Z 31(627) DEBUG: xhttp [xhttp_mod.c:372]: xhttp_handler(): new fake msg created (332 bytes):
2024-09-04T09:46:07.753907767Z <GET / HTTP/1.1
2024-09-04T09:46:07.753911101Z Via: SIP/2.0/TCP 11.15.32.1:33333
2024-09-04T09:46:07.753914881Z X-Special: James special websocket client
2024-09-04T09:46:07.753918651Z Sec-WebSocket-Version: 13
2024-09-04T09:46:07.753922268Z Sec-WebSocket-Key: BusZNu+n1GkrSfuhBvbLQQ==
2024-09-04T09:46:07.753926234Z Connection: Upgrade
2024-09-04T09:46:07.753930214Z Upgrade: websocket
2024-09-04T09:46:07.753939542Z Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
2024-09-04T09:46:07.753944397Z Sec-WebSocket-Protocol: sip
2024-09-04T09:46:07.753948538Z Host: sip.frideo.eu:80
2024-09-04T09:46:07.753952310Z 
2024-09-04T09:46:07.753957376Z >
2024-09-04T09:46:07.754196694Z 31(627) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 1 (request) flags 2
2024-09-04T09:46:07.754204858Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:721]: parse_msg(): SIP Request:
2024-09-04T09:46:07.754209564Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:723]: parse_msg():  method:  <GET>
2024-09-04T09:46:07.754213822Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:725]: parse_msg():  uri:     </>
2024-09-04T09:46:07.754218008Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:727]: parse_msg():  version: <HTTP/1.1>
2024-09-04T09:46:07.754222042Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:07.754225956Z 31(627) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:07.754229886Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:07.754234144Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:07.754238129Z 31(627) INFO: <script>: HTTP Request Received from 11.15.32.1:33333
2024-09-04T09:46:07.754276823Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Special] type 0
2024-09-04T09:46:07.754281163Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.754288590Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.754310421Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.754315236Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.754319812Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Extensions] type 0
2024-09-04T09:46:07.754324328Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.754328327Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754332482Z 31(627) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
2024-09-04T09:46:07.754336690Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:07.754341919Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.754346269Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Special] type 0
2024-09-04T09:46:07.754350370Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.754354777Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.754359115Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.754433303Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.754439474Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.754443759Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.754448129Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.754452829Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.754457201Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.754461331Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:07.754465604Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.754496808Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Special] type 0
2024-09-04T09:46:07.754502609Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.754506928Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.754511590Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.754516557Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.754520918Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.754525339Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.754529589Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.754533671Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:07.754537838Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754542059Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Special] type 0
2024-09-04T09:46:07.754546351Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754550379Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.754554733Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754559232Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.754585820Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754590552Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.754595205Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754599544Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.754603971Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754608313Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Extensions] type 0
2024-09-04T09:46:07.754618677Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754623290Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.754627628Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754632397Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754636704Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754640820Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:07.754644868Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754822037Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Special] type 0
2024-09-04T09:46:07.754827591Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754831960Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.754836095Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754840280Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.754843854Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754847829Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.754851896Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754856190Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.754860234Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754864225Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Extensions] type 0
2024-09-04T09:46:07.754869061Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754873187Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.754959213Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754966613Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754970664Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.754974262Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==11 && [sip.frideo.eu] == [10.25.17.11]
2024-09-04T09:46:07.754978392Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 80
2024-09-04T09:46:07.754982771Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==12 && [sip.frideo.eu] == [198.18.55.66]
2024-09-04T09:46:07.754986693Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 80
2024-09-04T09:46:07.754990615Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==12 && [sip.frideo.eu] == [198.18.55.66]
2024-09-04T09:46:07.754995092Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 9090 (advertise 0) matches port 80
2024-09-04T09:46:07.754999409Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==12 && [sip.frideo.eu] == [11.255.1.160]
2024-09-04T09:46:07.755003507Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 80
2024-09-04T09:46:07.755007246Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==12 && [sip.frideo.eu] == [11.15.32.160]
2024-09-04T09:46:07.755010889Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 9060 (advertise 0) matches port 80
2024-09-04T09:46:07.755014650Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==11 && [sip.frideo.eu] == [10.25.17.11]
2024-09-04T09:46:07.755191222Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 80
2024-09-04T09:46:07.755200822Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==12 && [sip.frideo.eu] == [198.18.55.66]
2024-09-04T09:46:07.755206052Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 80
2024-09-04T09:46:07.755210498Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==12 && [sip.frideo.eu] == [198.18.55.66]
2024-09-04T09:46:07.755215339Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 9090 (advertise 0) matches port 80
2024-09-04T09:46:07.755219722Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==12 && [sip.frideo.eu] == [198.18.55.66]
2024-09-04T09:46:07.755234159Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 80 (advertise 0) matches port 80
2024-09-04T09:46:07.755239430Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==12 && [sip.frideo.eu] == [11.255.1.160]
2024-09-04T09:46:07.755244061Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 80
2024-09-04T09:46:07.755271195Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==12 && [sip.frideo.eu] == [11.15.32.160]
2024-09-04T09:46:07.755276321Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 9090 (advertise 0) matches port 80
2024-09-04T09:46:07.755280887Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==11 && [sip.frideo.eu] == [10.25.17.11]
2024-09-04T09:46:07.755286033Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5061 (advertise 0) matches port 80
2024-09-04T09:46:07.755290347Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==12 && [sip.frideo.eu] == [198.18.55.66]
2024-09-04T09:46:07.755295147Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5061 (advertise 0) matches port 80
2024-09-04T09:46:07.755299780Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==12 && [sip.frideo.eu] == [198.18.55.66]
2024-09-04T09:46:07.755304629Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 9091 (advertise 0) matches port 80
2024-09-04T09:46:07.755310076Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==12 && [sip.frideo.eu] == [198.18.55.66]
2024-09-04T09:46:07.755314984Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 443 (advertise 0) matches port 80
2024-09-04T09:46:07.755319628Z 31(627) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 13==12 && [sip.frideo.eu] == [11.255.1.160]
2024-09-04T09:46:07.755324342Z 31(627) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5061 (advertise 0) matches port 80
2024-09-04T09:46:07.755328860Z 31(627) DEBUG: <core> [core/name_alias.h:63]: grep_aliases(): matching (0:sip.frideo.eu:80) vs. (0:sip-anycast2.frideo.eu:0)
2024-09-04T09:46:07.755342383Z 31(627) DEBUG: <core> [core/name_alias.h:63]: grep_aliases(): matching (0:sip.frideo.eu:80) vs. (0:sip-anycast1.frideo.eu:0)
2024-09-04T09:46:07.755347768Z 31(627) DEBUG: <core> [core/name_alias.h:63]: grep_aliases(): matching (0:sip.frideo.eu:80) vs. (0:sip.frideo.eu:0)
2024-09-04T09:46:07.755352636Z 31(627) DEBUG: <core> [core/forward.c:447]: check_self(): host (0:sip.frideo.eu:80) == me
2024-09-04T09:46:07.755357044Z 31(627) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:07.755366669Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:07.755371596Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.755424715Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:07.755437639Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.755442322Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:07.755446473Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.755451043Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:07.755455786Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.755461602Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:07.755466095Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.755470566Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:07.755475039Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Origin] type 0
2024-09-04T09:46:07.755479905Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Special] type 0
2024-09-04T09:46:07.755544121Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.755550283Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Special] type 0
2024-09-04T09:46:07.755555118Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.755559661Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Special] type 0
2024-09-04T09:46:07.755563760Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.755568386Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Special] type 0
2024-09-04T09:46:07.755573334Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.755577826Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Special] type 0
2024-09-04T09:46:07.755724001Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.755736530Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Special] type 0
2024-09-04T09:46:07.755741976Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Origin] type 0
2024-09-04T09:46:07.755746592Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.755877985Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.755885421Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.755890281Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.755894833Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.755899558Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.755904162Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.755909044Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.755913735Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.756173129Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.756191380Z 31(627) DEBUG: websocket [ws_handshake.c:242]: ws_handle_handshake(): found Sec-WebSocket-Version: 13
2024-09-04T09:46:07.756196595Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.756200455Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.756204447Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.756208236Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.756212192Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.756215903Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.756227294Z 31(627) DEBUG: websocket [ws_handshake.c:195]: ws_handle_handshake(): found Sec-WebSocket-Key: BusZNu+n1GkrSfuhBvbLQQ==
2024-09-04T09:46:07.756232415Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.756236766Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.756241121Z 31(627) DEBUG: websocket [ws_handshake.c:167]: ws_handle_handshake(): found Connection: upgrade
2024-09-04T09:46:07.756245294Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.756249557Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.756254309Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.756258534Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.756262920Z 31(627) DEBUG: websocket [ws_handshake.c:179]: ws_handle_handshake(): found Upgrade: websocket
2024-09-04T09:46:07.756266767Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Extensions] type 0
2024-09-04T09:46:07.756271162Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.756275489Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Extensions] type 0
2024-09-04T09:46:07.756279520Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.756284287Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Extensions] type 0
2024-09-04T09:46:07.756288851Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.756292710Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Extensions] type 0
2024-09-04T09:46:07.756297134Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.756302204Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Extensions] type 0
2024-09-04T09:46:07.756306392Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.756310888Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Extensions] type 0
2024-09-04T09:46:07.756321943Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Origin] type 0
2024-09-04T09:46:07.756326916Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.756331031Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.756335342Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.756340270Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.756344934Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.756349763Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.756354444Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.756359031Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.756363808Z 31(627) DEBUG: websocket [ws_handshake.c:206]: ws_handle_handshake(): found Sec-WebSocket-Protocol: sip
2024-09-04T09:46:07.756368070Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.756372585Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Connection] type 0
2024-09-04T09:46:07.756376859Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.756381124Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Upgrade] type 0
2024-09-04T09:46:07.756385818Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.756389904Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Key] type 0
2024-09-04T09:46:07.756394256Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.756398689Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Protocol] type 0
2024-09-04T09:46:07.756403095Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.756407819Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Sec-WebSocket-Version] type 0
2024-09-04T09:46:07.756412098Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Host] type 0
2024-09-04T09:46:07.756422398Z 31(627) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Origin] type 0
2024-09-04T09:46:07.756427729Z 31(627) DEBUG: websocket [ws_conn.c:195]: wsconn_add(): connection id [1]
2024-09-04T09:46:07.756431544Z 31(627) DEBUG: websocket [ws_conn.c:213]: wsconn_add(): new wsc => [0x7f71ed7f99c0], ref => [0]
2024-09-04T09:46:07.756436038Z 31(627) DEBUG: websocket [ws_conn.c:232]: wsconn_add(): added to conn_table wsc => [0x7f71ed7f99c0], ref => [1]
2024-09-04T09:46:07.756440626Z 31(627) DEBUG: sl [sl.c:306]: send_reply(): reply in stateless mode (sl)
2024-09-04T09:46:07.756444753Z 31(627) DEBUG: <core> [core/msg_translator.c:162]: check_via_address(): (11.15.32.1, 11.15.32.1, 0)
2024-09-04T09:46:07.756449225Z 31(627) DEBUG: sl [sl_funcs.c:564]: sl_run_callbacks(): execute callback for event type 1
2024-09-04T09:46:07.756453347Z 31(627) DEBUG: siptrace [siptrace.c:1985]: trace_sl_onreply_out(): trace off...
2024-09-04T09:46:07.756457718Z 31(627) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:07.756461811Z 31(627) DEBUG: <core> [core/tcp_main.c:2618]: tcpconn_send_put(): send from reader (627 (31)), reusing fd
2024-09-04T09:46:07.756466345Z 31(627) DEBUG: <core> [core/tcp_main.c:2849]: tcpconn_do_send(): sending...
2024-09-04T09:46:07.756470431Z 31(627) DEBUG: <core> [core/tcp_main.c:2885]: tcpconn_do_send(): after real write: c= 0x7f71ed7f52d0 n=258 fd=14
2024-09-04T09:46:07.756474706Z 31(627) DEBUG: <core> [core/tcp_main.c:2886]: tcpconn_do_send(): buf=
2024-09-04T09:46:07.756478874Z HTTP/1.1 101 Switching Protocols
2024-09-04T09:46:07.756483043Z Sia: SIP/2.0/TCP 11.15.32.1:33333
2024-09-04T09:46:07.756487871Z Sec-WebSocket-Protocol: sip
2024-09-04T09:46:07.756492037Z Upgrade: websocket
2024-09-04T09:46:07.756495998Z Connection: upgrade
2024-09-04T09:46:07.756499998Z Sec-WebSocket-Accept: 9T//rnFY9NnFuZDn1UNPh7qqmZQ=
2024-09-04T09:46:07.756504352Z Server: kamailio (6.0.0-dev2 (x86_64/linux))
2024-09-04T09:46:07.756508646Z Content-Length: 0
2024-09-04T09:46:07.756512680Z 
2024-09-04T09:46:07.756516403Z 
2024-09-04T09:46:07.756520217Z 31(627) WARNING: <script>: P0772 HTTP handshake completed (from 11.15.32.1:33333 to 198.18.55.66:80)
2024-09-04T09:46:07.756524501Z 31(627) DEBUG: <core> [core/receive.c:435]: receive_msg(): finished handling non-sip request message
2024-09-04T09:46:07.756528395Z 31(627) DEBUG: <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
2024-09-04T09:46:07.756532638Z 31(627) DEBUG: <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
2024-09-04T09:46:07.756536768Z 31(627) DEBUG: <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
2024-09-04T09:46:07.756546331Z 31(627) DEBUG: <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
2024-09-04T09:46:07.756550766Z 31(627) DEBUG: <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
2024-09-04T09:46:07.756555207Z 31(627) DEBUG: <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
2024-09-04T09:46:07.756559633Z 31(627) DEBUG: <core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
2024-09-04T09:46:07.756564242Z 31(627) DEBUG: <core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
2024-09-04T09:46:07.756568360Z 31(627) DEBUG: <core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
2024-09-04T09:46:07.756573061Z 31(627) DEBUG: <core> [core/receive.c:635]: receive_msg(): cleaning up
2024-09-04T09:46:08.482881472Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:09.483452397Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:10.484500879Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:11.485124822Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:12.486173528Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:13.487227844Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:13.761119564Z 31(627) DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x55dda9722f40, 14, -1, 0x10) fd_no=2 called
2024-09-04T09:46:13.761147950Z 31(627) DEBUG: <core> [core/tcp_read.c:1696]: release_tcpconn(): releasing con 0x7f71ed7f52d0, state 1, fd=14, id=1 ([11.15.32.1]:33333 -> [11.15.32.1]:80)
2024-09-04T09:46:13.761154313Z 31(627) DEBUG: <core> [core/tcp_read.c:1699]: release_tcpconn(): extra_data (nil)
2024-09-04T09:46:13.761159057Z 46(642) DEBUG: <core> [core/tcp_main.c:3773]: handle_tcp_child(): reader response= 7f71ed7f52d0, 1 from 0 
2024-09-04T09:46:13.761162851Z 46(642) DEBUG: <core> [core/io_wait.h:369]: io_watch_add(): processing io_watch_add(0x55dda96c6da0, 121, 2, 0x7f71ed7f52d0) - fd_no=71
2024-09-04T09:46:13.761168206Z 46(642) DEBUG: <core> [core/tcp_main.c:3905]: handle_tcp_child(): CONN_RELEASE  0x7f71ed7f52d0 refcnt= 1
2024-09-04T09:46:14.488279493Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:15.489188597Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:15.932861513Z  1(597) DEBUG: <core> [core/receive.c:136]: sip_check_fline(): first line indicates a SIP request
2024-09-04T09:46:15.932900219Z  1(597) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 1 (request) flags 1
2024-09-04T09:46:15.932920760Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:721]: parse_msg(): SIP Request:
2024-09-04T09:46:15.932925847Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:723]: parse_msg():  method:  <INVITE>
2024-09-04T09:46:15.932930253Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:725]: parse_msg():  uri:     <sip:moon@bobbywomack.invalid;alias=11.15.32.1~33333~6;transport=ws>
2024-09-04T09:46:15.932934739Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:727]: parse_msg():  version: <SIP/2.0>
2024-09-04T09:46:15.932959161Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:15.932967259Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 235, <rport> = <n/a>; state=6
2024-09-04T09:46:15.933157790Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-d8754z-cc2c63344f5218d>; state=16
2024-09-04T09:46:15.933173929Z  1(597) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:15.933179643Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:15.933184405Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:15.933188296Z  1(597) DEBUG: siptrace [siptrace.c:2335]: siptrace_net_data_recv(): processing message mode 1
2024-09-04T09:46:15.933309117Z  1(597) DEBUG: siptrace [siptrace_hep.c:523]: pipport2su(): the port string is 5060
2024-09-04T09:46:15.933317537Z  1(597) DEBUG: siptrace [siptrace_hep.c:523]: pipport2su(): the port string is 5060
2024-09-04T09:46:15.933322481Z  1(597) DEBUG: <core> [core/proxy.c:267]: mk_proxy(): doing DNS lookup...
2024-09-04T09:46:15.933326909Z  1(597) DEBUG: siptrace [siptrace_hep.c:185]: trace_send_hep3_duplicate(): setting up the socket_info
2024-09-04T09:46:15.933331335Z  1(597) DEBUG: siptrace [siptrace_hep.c:200]: trace_send_hep3_duplicate(): send sock addr activated - find the sock_info
2024-09-04T09:46:15.933429699Z  1(597) DEBUG: siptrace [siptrace_hep.c:212]: trace_send_hep3_duplicate(): found send socket: [11.15.32.160] [11.15.32.160]
2024-09-04T09:46:15.933439722Z  1(597) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 1 (request) flags 1
2024-09-04T09:46:15.933444935Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:721]: parse_msg(): SIP Request:
2024-09-04T09:46:15.933449634Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:723]: parse_msg():  method:  <INVITE>
2024-09-04T09:46:15.933454168Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:725]: parse_msg():  uri:     <sip:moon@bobbywomack.invalid;alias=11.15.32.1~33333~6;transport=ws>
2024-09-04T09:46:15.933458983Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:727]: parse_msg():  version: <SIP/2.0>
2024-09-04T09:46:15.933473222Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:15.933478616Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 235, <rport> = <n/a>; state=6
2024-09-04T09:46:15.933483378Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-d8754z-cc2c63344f5218d>; state=16
2024-09-04T09:46:15.933488508Z  1(597) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:15.933492849Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:15.933497065Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:15.933502414Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Route] type 9
2024-09-04T09:46:15.933506523Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Route] type 9
2024-09-04T09:46:15.933510197Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [From] type 4
2024-09-04T09:46:15.933514205Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [To] type 3
2024-09-04T09:46:15.933518135Z  1(597) DEBUG: <core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=10
2024-09-04T09:46:15.933522149Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [34]; uri=[sip:+35315220000@sip.frideo.eu]
2024-09-04T09:46:15.933526128Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (34)[<sip:+35315220000@sip.frideo.eu>
2024-09-04T09:46:15.933530245Z ], to tag (0)[]
2024-09-04T09:46:15.933534052Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Contact] type 7
2024-09-04T09:46:15.933538375Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Call-ID] type 6
2024-09-04T09:46:15.933542691Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [CSeq] type 5
2024-09-04T09:46:15.933546432Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1244552063> <INVITE>
2024-09-04T09:46:15.933550572Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Max-Forwards] type 8
2024-09-04T09:46:15.933554568Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Content-Length] type 12
2024-09-04T09:46:15.933558554Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
2024-09-04T09:46:15.933562144Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
2024-09-04T09:46:15.933572355Z  1(597) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 1 (request) flags 1
2024-09-04T09:46:15.933576872Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:721]: parse_msg(): SIP Request:
2024-09-04T09:46:15.933580818Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:723]: parse_msg():  method:  <INVITE>
2024-09-04T09:46:15.933587335Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:725]: parse_msg():  uri:     <sip:moon@bobbywomack.invalid;alias=11.15.32.1~33333~6;transport=ws>
2024-09-04T09:46:15.933591739Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:727]: parse_msg():  version: <SIP/2.0>
2024-09-04T09:46:15.933595704Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:15.933599742Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 235, <rport> = <n/a>; state=6
2024-09-04T09:46:15.933603819Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-d8754z-cc2c63344f5218d>; state=16
2024-09-04T09:46:15.933608117Z  1(597) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:15.933611662Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:15.933615252Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:15.933619430Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Route] type 9
2024-09-04T09:46:15.933623599Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Route] type 9
2024-09-04T09:46:15.933627909Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [From] type 4
2024-09-04T09:46:15.933631882Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [To] type 3
2024-09-04T09:46:15.933635553Z  1(597) DEBUG: <core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=10
2024-09-04T09:46:15.933639242Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [34]; uri=[sip:+35315220000@sip.frideo.eu]
2024-09-04T09:46:15.933643069Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (34)[<sip:+35315220000@sip.frideo.eu>
2024-09-04T09:46:15.933646664Z ], to tag (0)[]
2024-09-04T09:46:15.933649819Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Contact] type 7
2024-09-04T09:46:15.933654047Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Call-ID] type 6
2024-09-04T09:46:15.933663679Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [CSeq] type 5
2024-09-04T09:46:15.933669451Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1244552063> <INVITE>
2024-09-04T09:46:15.933674179Z  1(597) DEBUG: <core> [core/receive.c:392]: receive_msg(): --- received sip message - request - call-id: [te-e4d31-c287-4a7c-8c8a-1244552063] - cseq: [1244552063 INVITE]
2024-09-04T09:46:15.934160705Z  1(597) DEBUG: <core> [core/receive.c:263]: ksr_evrt_pre_routing(): event route core:pre-routing not defined
2024-09-04T09:46:15.934208115Z  1(597) DEBUG: <core> [core/receive.c:474]: receive_msg(): preparing to run routing scripts...
2024-09-04T09:46:15.934214619Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Max-Forwards] type 8
2024-09-04T09:46:15.934219245Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Content-Length] type 12
2024-09-04T09:46:15.934224193Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
2024-09-04T09:46:15.934228485Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
2024-09-04T09:46:15.934233174Z  1(597) DEBUG: siputils [checks.c:182]: has_totag(): no totag
2024-09-04T09:46:15.934237355Z  1(597) DEBUG: <core> [core/select.c:449]: run_select(): Calling SELECT 0x7f72369ea910
2024-09-04T09:46:15.934241761Z  1(597) DEBUG: <core> [core/select.c:449]: run_select(): Calling SELECT 0x7f72369ed0d0
2024-09-04T09:46:15.934246146Z  1(597) DEBUG: pv [pv_core.c:1095]: pv_get_useragent(): no User-Agent header
2024-09-04T09:46:15.934250600Z  1(597) DEBUG: pv [pv_core.c:1559]: pv_get_authattr(): no [Proxy-]Authorization header
2024-09-04T09:46:15.934255054Z  1(597) DEBUG: sanity [sanity.c:254]: check_ruri_sip_version(): check_ruri_sip_version entered
2024-09-04T09:46:15.934259532Z  1(597) DEBUG: sanity [sanity.c:278]: check_ruri_sip_version(): check_ruri_sip_version passed
2024-09-04T09:46:15.934263637Z  1(597) DEBUG: sanity [sanity.c:286]: check_ruri_scheme(): check_ruri_scheme entered
2024-09-04T09:46:15.934267915Z  1(597) DEBUG: sanity [sanity.c:305]: check_ruri_scheme(): check_ruri_scheme passed
2024-09-04T09:46:15.934271987Z  1(597) DEBUG: sanity [sanity.c:327]: check_required_headers(): check_required_headers entered
2024-09-04T09:46:15.934276428Z  1(597) DEBUG: sanity [sanity.c:350]: check_required_headers(): check_required_headers passed
2024-09-04T09:46:15.934280779Z  1(597) DEBUG: sanity [sanity.c:519]: check_cseq_method(): check_cseq_method entered
2024-09-04T09:46:15.934285159Z  1(597) DEBUG: sanity [sanity.c:553]: check_cseq_method(): check_cseq_method passed
2024-09-04T09:46:15.934289108Z  1(597) DEBUG: sanity [sanity.c:563]: check_cseq_value(): check_cseq_value entered
2024-09-04T09:46:15.934652928Z  1(597) DEBUG: sanity [sanity.c:591]: check_cseq_value(): check_cseq_value passed
2024-09-04T09:46:15.934668598Z  1(597) DEBUG: sanity [sanity.c:601]: check_cl(): check_cl entered
2024-09-04T09:46:15.934736285Z  1(597) DEBUG: sanity [sanity.c:626]: check_cl(): check_cl passed
2024-09-04T09:46:15.934742806Z  1(597) DEBUG: sanity [sanity.c:639]: check_expires_value(): check_expires_value entered
2024-09-04T09:46:15.934747173Z  1(597) DEBUG: sanity [sanity.c:675]: check_expires_value(): no expires header found
2024-09-04T09:46:15.934751095Z  1(597) DEBUG: sanity [sanity.c:772]: check_parse_uris(): check_parse_uris entered
2024-09-04T09:46:15.934755115Z  1(597) DEBUG: sanity [sanity.c:776]: check_parse_uris(): parsing ruri
2024-09-04T09:46:15.934759332Z  1(597) DEBUG: sanity [sanity.c:789]: check_parse_uris(): looking up From header
2024-09-04T09:46:15.934763349Z  1(597) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=1a56f142c2ed4d2f
2024-09-04T09:46:15.934767768Z  1(597) DEBUG: <core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=29
2024-09-04T09:46:15.934772247Z  1(597) DEBUG: sanity [sanity.c:804]: check_parse_uris(): looking up To header
2024-09-04T09:46:15.934776287Z  1(597) DEBUG: sanity [sanity.c:854]: check_parse_uris(): check_parse_uris passed
2024-09-04T09:46:15.934779903Z  1(597) DEBUG: sanity [sanity_mod.c:252]: w_sanity_check(): sanity checks result: 1
2024-09-04T09:46:15.934784076Z  1(597) DEBUG: siputils [checks.c:182]: has_totag(): no totag
2024-09-04T09:46:15.934787947Z  1(597) DEBUG: <script>: [te-e4d31-c287-4a7c-8c8a-1244552063] Adding Route header to REGISTER message
2024-09-04T09:46:15.934792154Z  1(597) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 11==11 && [10.25.17.11] == [10.25.17.11]
2024-09-04T09:46:15.934910991Z  1(597) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060
2024-09-04T09:46:15.934916107Z  1(597) DEBUG: <core> [core/forward.c:447]: check_self(): host (0:10.25.17.11:5060) == me
2024-09-04T09:46:15.934920514Z  1(597) DEBUG: rr [loose.c:1135]: redo_route_params(): Topmost route URI: 'sip:10.25.17.11;lr;r2=on' is me
2024-09-04T09:46:15.934924540Z  1(597) DEBUG: rr [loose.c:1325]: is_direction(): param ftag not found
2024-09-04T09:46:15.934928525Z  1(597) DEBUG: rr [record.c:489]: record_route(): inserted record route (r2: 1 - plen: 0)
2024-09-04T09:46:15.934932334Z  1(597) DEBUG: tm [t_lookup.c:1565]: t_check_msg(): msg (0x7f7236d44bf0) id=1/597 global id=0/0 T start=0xffffffffffffffff
2024-09-04T09:46:15.935068427Z  1(597) DEBUG: tm [t_lookup.c:781]: t_lookup_request(): start searching: hash=5853, isACK=0
2024-09-04T09:46:15.935073983Z  1(597) DEBUG: tm [t_lookup.c:499]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK-d8754z-cc2c63344f5218d]
2024-09-04T09:46:15.935079774Z  1(597) DEBUG: tm [t_lookup.c:981]: t_lookup_request(): no transaction found
2024-09-04T09:46:15.935084425Z  1(597) DEBUG: tm [t_lookup.c:1637]: t_check_msg(): msg (0x7f7236d44bf0) id=1/597 global id=1/597 T end=(nil)
2024-09-04T09:46:15.935098616Z  1(597) INFO: <script>: [te-e4d31-c287-4a7c-8c8a-1244552063] Initial INVITE received from 11.15.32.1:5060 to moon@bobbywomack.invalid:5060;transport=ws
2024-09-04T09:46:15.935104203Z  1(597) DEBUG: maxfwd [mf_funcs.c:74]: is_maxfwd_present(): value = 10 
2024-09-04T09:46:15.935108524Z  1(597) DEBUG: <script>: [te-e4d31-c287-4a7c-8c8a-1244552063] Removing some X-headers before relaying INVITE message
2024-09-04T09:46:15.935131432Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:15.935136253Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Encode-Contact-Header] type 0
2024-09-04T09:46:15.935140857Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Route] type 9
2024-09-04T09:46:15.935145644Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Encode-Contact-Header] type 0
2024-09-04T09:46:15.935150292Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Route] type 9
2024-09-04T09:46:15.935155130Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Encode-Contact-Header] type 0
2024-09-04T09:46:15.935160231Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [From] type 4
2024-09-04T09:46:15.935164764Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Encode-Contact-Header] type 0
2024-09-04T09:46:15.935169804Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [To] type 3
2024-09-04T09:46:15.935175515Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Encode-Contact-Header] type 0
2024-09-04T09:46:15.935180606Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Contact] type 7
2024-09-04T09:46:15.935185037Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Encode-Contact-Header] type 0
2024-09-04T09:46:15.935189584Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Call-ID] type 6
2024-09-04T09:46:15.935194267Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Encode-Contact-Header] type 0
2024-09-04T09:46:15.935204046Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [CSeq] type 5
2024-09-04T09:46:15.935208927Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Encode-Contact-Header] type 0
2024-09-04T09:46:15.935213696Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Max-Forwards] type 8
2024-09-04T09:46:15.935218472Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Encode-Contact-Header] type 0
2024-09-04T09:46:15.935223229Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Content-Length] type 12
2024-09-04T09:46:15.935227979Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [X-Encode-Contact-Header] type 0
2024-09-04T09:46:15.935264896Z  1(597) ERROR: <script>: [te-e4d31-c287-4a7c-8c8a-1244552063] P1052 WS initial INVITE arrives without appropriate KSS header field
2024-09-04T09:46:15.935481848Z  1(597) DEBUG: rr [loose.c:80]: is_preloaded(): is_preloaded: Yes
2024-09-04T09:46:15.935505878Z  1(597) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 11==11 && [10.25.17.11] == [10.25.17.11]
2024-09-04T09:46:15.935526243Z  1(597) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 5060
2024-09-04T09:46:15.935552156Z  1(597) DEBUG: <core> [core/forward.c:447]: check_self(): host (0:10.25.17.11:5060) == me
2024-09-04T09:46:15.935573976Z  1(597) DEBUG: rr [loose.c:886]: after_loose(): Topmost route URI: 'sip:10.25.17.11;lr;r2=on' is me
2024-09-04T09:46:15.935592984Z  1(597) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 12==11 && [198.18.55.66] == [10.25.17.11]
2024-09-04T09:46:15.935616137Z  1(597) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 443
2024-09-04T09:46:15.935636947Z  1(597) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 12==12 && [198.18.55.66] == [198.18.55.66]
2024-09-04T09:46:15.935661661Z  1(597) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 443
2024-09-04T09:46:15.935683100Z  1(597) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 12==12 && [198.18.55.66] == [198.18.55.66]
2024-09-04T09:46:15.935704662Z  1(597) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 9090 (advertise 0) matches port 443
2024-09-04T09:46:15.935726300Z  1(597) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 12==12 && [198.18.55.66] == [198.18.55.66]
2024-09-04T09:46:15.935748130Z  1(597) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 80 (advertise 0) matches port 443
2024-09-04T09:46:15.935783057Z  1(597) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 12==12 && [198.18.55.66] == [11.255.1.160]
2024-09-04T09:46:15.935807519Z  1(597) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5060 (advertise 0) matches port 443
2024-09-04T09:46:15.935827300Z  1(597) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 12==12 && [198.18.55.66] == [11.15.32.160]
2024-09-04T09:46:15.935850802Z  1(597) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 9090 (advertise 0) matches port 443
2024-09-04T09:46:15.935869743Z  1(597) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 12==11 && [198.18.55.66] == [10.25.17.11]
2024-09-04T09:46:15.935891110Z  1(597) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5061 (advertise 0) matches port 443
2024-09-04T09:46:15.935911842Z  1(597) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 12==12 && [198.18.55.66] == [198.18.55.66]
2024-09-04T09:46:15.935926978Z  1(597) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 5061 (advertise 0) matches port 443
2024-09-04T09:46:15.935936278Z  1(597) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 12==12 && [198.18.55.66] == [198.18.55.66]
2024-09-04T09:46:15.935941950Z  1(597) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 9091 (advertise 0) matches port 443
2024-09-04T09:46:15.935947082Z  1(597) DEBUG: <core> [core/socket_info.c:737]: grep_sock_info(): checking if host==us: 12==12 && [198.18.55.66] == [198.18.55.66]
2024-09-04T09:46:15.935952545Z  1(597) DEBUG: <core> [core/socket_info.c:741]: grep_sock_info(): checking if port 443 (advertise 0) matches port 443
2024-09-04T09:46:15.935957289Z  1(597) DEBUG: rr [loose.c:826]: rr_do_force_send_socket(): set send socket 0x7f723699d7e0 for local route uri: sip:198.18.55.66:443;transport=ws;lr;r2=on
2024-09-04T09:46:15.935962503Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
2024-09-04T09:46:15.935966615Z  1(597) DEBUG: rr [loose.c:181]: find_next_route(): No next Route HF found
2024-09-04T09:46:15.935970917Z  1(597) DEBUG: rr [loose.c:950]: after_loose(): no next URI found
2024-09-04T09:46:15.935975268Z  1(597) DEBUG: nathelper [nathelper.c:1251]: ki_handle_ruri_alias_mode(): setting dst_uri to <sip:11.15.32.1:33333;transport=ws>
2024-09-04T09:46:15.935980115Z  1(597) DEBUG: nathelper [nathelper.c:1273]: ki_handle_ruri_alias_mode(): rewriting r-uri to <sip:moon@bobbywomack.invalid;transport=ws>
2024-09-04T09:46:15.935984859Z  1(597) NOTICE: <script>: [te-e4d31-c287-4a7c-8c8a-1244552063] P1052 About to relay WS call to 11.15.32.1:33333 from tls:198.18.55.66:443 ($du is sip:11.15.32.1:33333;transport=ws)
2024-09-04T09:46:15.935989650Z  1(597) DEBUG: tm [t_lookup.c:1868]: t_newtran(): msg (0x7f7236d44bf0) id=1/597 global id=1/597 T start=(nil)
2024-09-04T09:46:15.936004062Z  1(597) DEBUG: tm [t_lookup.c:781]: t_lookup_request(): start searching: hash=5853, isACK=0
2024-09-04T09:46:15.936009940Z  1(597) DEBUG: tm [t_lookup.c:499]: matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK-d8754z-cc2c63344f5218d]
2024-09-04T09:46:15.936014243Z  1(597) DEBUG: tm [t_lookup.c:981]: t_lookup_request(): no transaction found
2024-09-04T09:46:15.936018346Z  1(597) DEBUG: <core> [core/crypto/md5utils.c:67]: MD5StringArray(): MD5 calculated: 5d8d0828a105147e0993a5685beacb98
2024-09-04T09:46:15.936022947Z  1(597) DEBUG: tm [h_table.c:415]: build_cell(): created new cell 0x7f71ed809c00
2024-09-04T09:46:15.936027094Z  1(597) DEBUG: tm [t_funcs.c:349]: t_relay_to(): new INVITE
2024-09-04T09:46:15.936031392Z  1(597) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 2 (reply(status)) flags 1
2024-09-04T09:46:15.936036252Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:731]: parse_msg(): SIP Reply  (status):
2024-09-04T09:46:15.936040518Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:733]: parse_msg():  version: <SIP/2.0>
2024-09-04T09:46:15.936044970Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:735]: parse_msg():  status:  <100>
2024-09-04T09:46:15.936049291Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:737]: parse_msg():  reason:  <Jamesb trying>
2024-09-04T09:46:15.936053344Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:15.936057756Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
2024-09-04T09:46:15.936062208Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-d8754z-cc2c63344f5218d>; state=6
2024-09-04T09:46:15.936067618Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 234, <received> = <11.15.32.1>; state=16
2024-09-04T09:46:15.936072654Z  1(597) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:15.936076711Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:15.936081007Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:15.936085115Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [From] type 4
2024-09-04T09:46:15.936089345Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [To] type 3
2024-09-04T09:46:15.936094610Z  1(597) DEBUG: <core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=10
2024-09-04T09:46:15.936099240Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [34]; uri=[sip:+35315220000@sip.frideo.eu]
2024-09-04T09:46:15.936110351Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (34)[<sip:+35315220000@sip.frideo.eu>
2024-09-04T09:46:15.936115414Z ], to tag (0)[]
2024-09-04T09:46:15.936119152Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Call-ID] type 6
2024-09-04T09:46:15.936123424Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [CSeq] type 5
2024-09-04T09:46:15.936127920Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1244552063> <INVITE>
2024-09-04T09:46:15.936132569Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Server] type 29
2024-09-04T09:46:15.936137432Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Content-Length] type 12
2024-09-04T09:46:15.936141568Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
2024-09-04T09:46:15.936145646Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
2024-09-04T09:46:15.936149959Z  1(597) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 2 (reply(status)) flags 1
2024-09-04T09:46:15.936154287Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:731]: parse_msg(): SIP Reply  (status):
2024-09-04T09:46:15.936158622Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:733]: parse_msg():  version: <SIP/2.0>
2024-09-04T09:46:15.936163078Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:735]: parse_msg():  status:  <100>
2024-09-04T09:46:15.936167166Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:737]: parse_msg():  reason:  <Jamesb trying>
2024-09-04T09:46:15.936171524Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:15.936175761Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
2024-09-04T09:46:15.936180589Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-d8754z-cc2c63344f5218d>; state=6
2024-09-04T09:46:15.936185645Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 234, <received> = <11.15.32.1>; state=16
2024-09-04T09:46:15.936190058Z  1(597) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:15.936194329Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:15.936198632Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:15.936202529Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [From] type 4
2024-09-04T09:46:15.936212326Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [To] type 3
2024-09-04T09:46:15.936216842Z  1(597) DEBUG: <core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=10
2024-09-04T09:46:15.936221386Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [34]; uri=[sip:+35315220000@sip.frideo.eu]
2024-09-04T09:46:15.936228643Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (34)[<sip:+35315220000@sip.frideo.eu>
2024-09-04T09:46:15.936233035Z ], to tag (0)[]
2024-09-04T09:46:15.936255006Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Call-ID] type 6
2024-09-04T09:46:15.936260201Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [CSeq] type 5
2024-09-04T09:46:15.936264707Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1244552063> <INVITE>
2024-09-04T09:46:15.936269617Z  1(597) DEBUG: siptrace [siptrace.c:2476]: siptrace_net_data_sent(): processing message mode 1
2024-09-04T09:46:15.936274030Z  1(597) DEBUG: siptrace [siptrace_hep.c:523]: pipport2su(): the port string is 5060
2024-09-04T09:46:15.936278088Z  1(597) DEBUG: siptrace [siptrace_hep.c:523]: pipport2su(): the port string is 5060
2024-09-04T09:46:15.936282464Z  1(597) DEBUG: <core> [core/proxy.c:267]: mk_proxy(): doing DNS lookup...
2024-09-04T09:46:15.936286406Z  1(597) DEBUG: siptrace [siptrace_hep.c:185]: trace_send_hep3_duplicate(): setting up the socket_info
2024-09-04T09:46:15.936290609Z  1(597) DEBUG: siptrace [siptrace_hep.c:200]: trace_send_hep3_duplicate(): send sock addr activated - find the sock_info
2024-09-04T09:46:15.936294855Z  1(597) DEBUG: siptrace [siptrace_hep.c:212]: trace_send_hep3_duplicate(): found send socket: [11.15.32.160] [11.15.32.160]
2024-09-04T09:46:15.936299633Z  1(597) DEBUG: tm [t_reply.c:634]: _reply_light(): reply sent out - buf=0x7f7236ac37f0: SIP/2.0 100 Jamesb t... shmem=0x7f71ed80d040: SIP/2.0 100 Jamesb t
2024-09-04T09:46:15.936304233Z  1(597) DEBUG: tm [t_reply.c:650]: _reply_light(): finished
2024-09-04T09:46:15.936324151Z  1(597) DEBUG: <core> [core/dns_cache.c:3256]: dns_srv_sip_resolve(): (11.15.32.1, 0, 0), ip, ret=0
2024-09-04T09:46:15.936329338Z  1(597) DEBUG: <core> [core/msg_translator.c:1869]: check_boundaries(): no multi-part body
2024-09-04T09:46:15.936333697Z  1(597) DEBUG: <core> [core/tcp_main.c:1746]: _tcpconn_find(): found connection by peer address (id: 1)
2024-09-04T09:46:15.936337900Z  1(597) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 1 (request) flags 1
2024-09-04T09:46:15.936342377Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:721]: parse_msg(): SIP Request:
2024-09-04T09:46:15.936346712Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:723]: parse_msg():  method:  <INVITE>
2024-09-04T09:46:15.936355949Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:725]: parse_msg():  uri:     <sip:moon@bobbywomack.invalid;transport=ws>
2024-09-04T09:46:15.936360847Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:727]: parse_msg():  version: <SIP/2.0>
2024-09-04T09:46:15.936365551Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Record-Route] type 10
2024-09-04T09:46:15.936370359Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Record-Route] type 10
2024-09-04T09:46:15.936374574Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:15.936379359Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKdd61.5d8d0828a105147e0993a5685beacb98.0>; state=16
2024-09-04T09:46:15.936383998Z  1(597) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:15.936388164Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:15.936392136Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:15.936396379Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:15.936401029Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 234, <received> = <11.15.32.1>; state=6
2024-09-04T09:46:15.936437005Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
2024-09-04T09:46:15.936443710Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-d8754z-cc2c63344f5218d>; state=16
2024-09-04T09:46:15.936449095Z  1(597) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:15.936453679Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=ffffffffffffffff
2024-09-04T09:46:15.936457913Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:604]: parse_headers(): this is the second via
2024-09-04T09:46:15.936461929Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [From] type 4
2024-09-04T09:46:15.936466491Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [To] type 3
2024-09-04T09:46:15.936470465Z  1(597) DEBUG: <core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=10
2024-09-04T09:46:15.936475065Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [34]; uri=[sip:+35315220000@sip.frideo.eu]
2024-09-04T09:46:15.936479983Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (34)[<sip:+35315220000@sip.frideo.eu>
2024-09-04T09:46:15.936489652Z ], to tag (0)[]
2024-09-04T09:46:15.936493669Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Contact] type 7
2024-09-04T09:46:15.936498307Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Call-ID] type 6
2024-09-04T09:46:15.936502518Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [CSeq] type 5
2024-09-04T09:46:15.936506930Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1244552063> <INVITE>
2024-09-04T09:46:15.936512016Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Max-Forwards] type 8
2024-09-04T09:46:15.936516326Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Content-Length] type 12
2024-09-04T09:46:15.936521018Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
2024-09-04T09:46:15.936525198Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
2024-09-04T09:46:15.936529441Z  1(597) DEBUG: <core> [core/tcp_main.c:1746]: _tcpconn_find(): found connection by peer address (id: 1)
2024-09-04T09:46:15.936534568Z  1(597) DEBUG: websocket [ws_conn.c:462]: wsconn_get(): wsconn_get for id [1]
2024-09-04T09:46:15.936538697Z  1(597) DEBUG: websocket [ws_conn.c:468]: wsconn_get(): wsconn_get id [1] returns wsc [0x7f71ed7f99c0] refcnt [2]
2024-09-04T09:46:15.936542663Z  1(597) DEBUG: websocket [ws_frame.c:739]: ws_frame_transmit(): Tx message:
2024-09-04T09:46:15.936546926Z INVITE sip:moon@bobbywomack.invalid;transport=ws SIP/2.0
2024-09-04T09:46:15.936551112Z Record-Route: <sip:198.18.55.66:443;transport=ws;r2=on;lr;ftag=1a56f142c2ed4d2f>
2024-09-04T09:46:15.936555616Z Record-Route: <sip:10.25.17.11;r2=on;lr;ftag=1a56f142c2ed4d2f>
2024-09-04T09:46:15.936559470Z Via: SIP/2.0/WS  198.18.55.66:443;branch=z9hG4bKdd61.5d8d0828a105147e0993a5685beacb98.0
2024-09-04T09:46:15.936563671Z Via: SIP/2.0/UDP 192.168.25.4:5060;received=11.15.32.1;rport=5060;branch=z9hG4bK-d8754z-cc2c63344f5218d
2024-09-04T09:46:15.936567746Z From: <sip:+353877900000@someclient>;tag=1a56f142c2ed4d2f
2024-09-04T09:46:15.936571895Z To: <sip:+35315220000@sip.frideo.eu>
2024-09-04T09:46:15.936576077Z Contact: <sip:+353877900000@10.24.12.4>
2024-09-04T09:46:15.936579871Z Call-ID: te-e4d31-c287-4a7c-8c8a-1244552063
2024-09-04T09:46:15.936584324Z CSeq: 1244552063 INVITE
2024-09-04T09:46:15.936587924Z Max-Forwards:  9
2024-09-04T09:46:15.936591475Z Content-Length: 0
2024-09-04T09:46:15.936594917Z 
2024-09-04T09:46:15.936598693Z 
2024-09-04T09:46:15.936607195Z  1(597) DEBUG: websocket [ws_frame.c:147]: encode_and_send_ws_frame(): encoding WebSocket frame
2024-09-04T09:46:15.936617697Z  1(597) DEBUG: websocket [ws_frame.c:173]: encode_and_send_ws_frame(): supported non-control frame: 0x1
2024-09-04T09:46:15.936622205Z  1(597) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:15.936626468Z  1(597) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:15.936631056Z  1(597) DEBUG: <core> [core/tcp_main.c:2634]: tcpconn_send_put(): tcp connection found (0x7f71ed7f52d0), acquiring fd
2024-09-04T09:46:15.936635253Z  1(597) DEBUG: <core> [core/tcp_main.c:2644]: tcpconn_send_put(): c=0x7f71ed7f52d0, n=16
2024-09-04T09:46:15.936639318Z 46(642) DEBUG: <core> [core/tcp_main.c:4011]: handle_ser_child(): read response= 7f71ed7f52d0, 2, fd -1 from 1 (597)
2024-09-04T09:46:15.936643698Z  1(597) DEBUG: <core> [core/tcp_main.c:2672]: tcpconn_send_put(): after receive_fd: c= 0x7f71ed7f52d0 n=8 fd=7
2024-09-04T09:46:15.936648008Z  1(597) DEBUG: <core> [core/tcp_main.c:2849]: tcpconn_do_send(): sending...
2024-09-04T09:46:15.936652574Z  1(597) DEBUG: <core> [core/tcp_main.c:2885]: tcpconn_do_send(): after real write: c= 0x7f71ed7f52d0 n=649 fd=7
2024-09-04T09:46:15.936656993Z  1(597) DEBUG: <core> [core/tcp_main.c:2886]: tcpconn_do_send(): buf=
2024-09-04T09:46:15.936660940Z ???~???INVITE sip:moon@bobbywomack.invalid;transport=ws SIP/2.0
2024-09-04T09:46:15.936666213Z Record-Route: <sip:198.18.55.66:443;transport=ws;r2=on;lr;ftag=1a56f142c2ed4d2f>
2024-09-04T09:46:15.936670418Z Record-Route: <sip:10.25.17.11;r2=on;lr;ftag=1a56f142c2ed4d2f>
2024-09-04T09:46:15.936674555Z Via: SIP/2.0/WS  198.18.55.66:443;branch=z9hG4bKdd61.5d8d0828a105147e0993a5685beacb98.0
2024-09-04T09:46:15.936678630Z Via: SIP/2.0/UDP 192.168.25.4:5060;received=11.15.32.1;rport=5060;branch=z9hG4bK-d8754z-cc2c63344f5218d
2024-09-04T09:46:15.936682516Z From: <sip:+353877900000@someclient>;tag=1a56f142c2ed4d2f
2024-09-04T09:46:15.936686822Z To: <sip:+35315220000@sip.frideo.eu>
2024-09-04T09:46:15.936690998Z Contact: <sip:+353877900000@10.24.12.4>
2024-09-04T09:46:15.936695423Z Call-ID: te-e4d31-c287-4a7c-8c8a-1244552063
2024-09-04T09:46:15.936699199Z CSeq: 1244552063 INVITE
2024-09-04T09:46:15.936703048Z Max-Forwards:  9
2024-09-04T09:46:15.936706394Z Content-Length: 0
2024-09-04T09:46:15.936710166Z 
2024-09-04T09:46:15.936714075Z 
2024-09-04T09:46:15.937551830Z  1(597) DEBUG: websocket [ws_conn.c:426]: wsconn_put_mode(): wsconn_put start for [0x7f71ed7f99c0] refcnt [2]
2024-09-04T09:46:15.937583141Z  1(597) DEBUG: websocket [ws_conn.c:440]: wsconn_put_mode(): wsconn_put end for [0x7f71ed7f99c0] refcnt [1]
2024-09-04T09:46:15.937589362Z  1(597) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 1 (request) flags 1
2024-09-04T09:46:15.937605713Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:721]: parse_msg(): SIP Request:
2024-09-04T09:46:15.937611534Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:723]: parse_msg():  method:  <INVITE>
2024-09-04T09:46:15.937616361Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:725]: parse_msg():  uri:     <sip:moon@bobbywomack.invalid;transport=ws>
2024-09-04T09:46:15.937620955Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:727]: parse_msg():  version: <SIP/2.0>
2024-09-04T09:46:15.937625580Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Record-Route] type 10
2024-09-04T09:46:15.937630328Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Record-Route] type 10
2024-09-04T09:46:15.937635204Z  1(597) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:15.937639676Z  1(597) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKdd61.5d8d0828a105147e0993a5685beacb98.0>; state=16
2024-09-04T09:46:15.937644940Z  1(597) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:15.937649393Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:15.937653991Z  1(597) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:15.937658518Z  1(597) DEBUG: siptrace [siptrace.c:2476]: siptrace_net_data_sent(): processing message mode 1
2024-09-04T09:46:15.937663056Z  1(597) DEBUG: siptrace [siptrace_hep.c:523]: pipport2su(): the port string is 443
2024-09-04T09:46:15.937667142Z  1(597) DEBUG: siptrace [siptrace_hep.c:523]: pipport2su(): the port string is 33333
2024-09-04T09:46:15.937671548Z  1(597) DEBUG: <core> [core/proxy.c:267]: mk_proxy(): doing DNS lookup...
2024-09-04T09:46:15.937675932Z  1(597) DEBUG: siptrace [siptrace_hep.c:185]: trace_send_hep3_duplicate(): setting up the socket_info
2024-09-04T09:46:15.937681513Z  1(597) DEBUG: siptrace [siptrace_hep.c:200]: trace_send_hep3_duplicate(): send sock addr activated - find the sock_info
2024-09-04T09:46:15.937686473Z  1(597) DEBUG: siptrace [siptrace_hep.c:212]: trace_send_hep3_duplicate(): found send socket: [11.15.32.160] [11.15.32.160]
2024-09-04T09:46:15.937690862Z  1(597) DEBUG: tm [t_funcs.c:396]: t_relay_to(): new transaction forwarded
2024-09-04T09:46:15.937695096Z  1(597) DEBUG: <core> [core/receive.c:532]: receive_msg(): request-route executed in: 3217 usec
2024-09-04T09:46:15.937699575Z  1(597) DEBUG: <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
2024-09-04T09:46:15.937704027Z  1(597) DEBUG: <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
2024-09-04T09:46:15.937708735Z  1(597) DEBUG: <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
2024-09-04T09:46:15.937719446Z  1(597) DEBUG: <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
2024-09-04T09:46:15.937724662Z  1(597) DEBUG: <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
2024-09-04T09:46:15.937729495Z  1(597) DEBUG: <core> [core/usr_avp.c:654]: destroy_avp_list(): destroying list (nil)
2024-09-04T09:46:15.937734132Z  1(597) DEBUG: <core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
2024-09-04T09:46:15.937738353Z  1(597) DEBUG: <core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
2024-09-04T09:46:15.937742966Z  1(597) DEBUG: <core> [core/xavp.c:630]: xavp_destroy_list(): destroying xavp list (nil)
2024-09-04T09:46:15.937747434Z  1(597) DEBUG: <core> [core/receive.c:635]: receive_msg(): cleaning up
2024-09-04T09:46:16.490198221Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:17.490987496Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:18.491779336Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:18.899839045Z 12(608) DEBUG: tm [timer.c:445]: final_response_handler(): send on branch 0 failed, adding another branch
2024-09-04T09:46:18.899870696Z 12(608) DEBUG: tm [h_table.c:532]: tm_xdata_swap(): copy X/AVPs from msg context to txdata
2024-09-04T09:46:18.900346128Z 12(608) DEBUG: tm [h_table.c:551]: tm_xdata_swap(): restore X/AVPs msg context from txdata
2024-09-04T09:46:18.900362806Z 12(608) DEBUG: tm [t_reply.c:1375]: t_should_relay_response(): ->>>>>>>>> T_code=100, new_code=408
2024-09-04T09:46:18.900368492Z 12(608) DEBUG: tm [t_reply.c:1609]: t_should_relay_response(): rps completed - uas status: 100 branch: 0
2024-09-04T09:46:18.900372848Z 12(608) DEBUG: tm [t_reply.c:1943]: relay_reply(): reply status=4 branch=0, save=0, relay=0 icode=0 msg status=408
2024-09-04T09:46:18.900545238Z 12(608) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 2 (reply(status)) flags 1
2024-09-04T09:46:18.900550954Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:731]: parse_msg(): SIP Reply  (status):
2024-09-04T09:46:18.900569575Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:733]: parse_msg():  version: <SIP/2.0>
2024-09-04T09:46:18.900574959Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:735]: parse_msg():  status:  <408>
2024-09-04T09:46:18.900579569Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:737]: parse_msg():  reason:  <Request Timeout>
2024-09-04T09:46:18.900651683Z 12(608) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:18.900889629Z 12(608) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
2024-09-04T09:46:18.900912089Z 12(608) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-d8754z-cc2c63344f5218d>; state=6
2024-09-04T09:46:18.900918537Z 12(608) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 234, <received> = <11.15.32.1>; state=16
2024-09-04T09:46:18.900923561Z 12(608) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:18.900928381Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:18.900932495Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:18.900936642Z 12(608) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [From] type 4
2024-09-04T09:46:18.900940960Z 12(608) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [To] type 3
2024-09-04T09:46:18.900944967Z 12(608) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=a87f9558cf5646d575962040dd7151c2-7dac3165
2024-09-04T09:46:18.900951328Z 12(608) DEBUG: <core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=29
2024-09-04T09:46:18.900956233Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [80]; uri=[sip:+35315220000@sip.frideo.eu]
2024-09-04T09:46:18.900960961Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (32)[<sip:+35315220000@sip.frideo.eu>], to tag (41)[a87f9558cf5646d575962040dd7151c2-7dac3165]
2024-09-04T09:46:18.900965446Z 12(608) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Call-ID] type 6
2024-09-04T09:46:18.900969450Z 12(608) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [CSeq] type 5
2024-09-04T09:46:18.900973375Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1244552063> <INVITE>
2024-09-04T09:46:18.900977768Z 12(608) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Server] type 29
2024-09-04T09:46:18.900981697Z 12(608) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Content-Length] type 12
2024-09-04T09:46:18.900985623Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
2024-09-04T09:46:18.900989900Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
2024-09-04T09:46:18.900993548Z 12(608) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 2 (reply(status)) flags 1
2024-09-04T09:46:18.901010502Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:731]: parse_msg(): SIP Reply  (status):
2024-09-04T09:46:18.901025580Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:733]: parse_msg():  version: <SIP/2.0>
2024-09-04T09:46:18.901036174Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:735]: parse_msg():  status:  <408>
2024-09-04T09:46:18.901041303Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:737]: parse_msg():  reason:  <Request Timeout>
2024-09-04T09:46:18.901045859Z 12(608) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:18.901049668Z 12(608) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
2024-09-04T09:46:18.901053577Z 12(608) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-d8754z-cc2c63344f5218d>; state=6
2024-09-04T09:46:18.901058398Z 12(608) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 234, <received> = <11.15.32.1>; state=16
2024-09-04T09:46:18.901062551Z 12(608) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:18.901066277Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:18.901069936Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:18.901073568Z 12(608) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [From] type 4
2024-09-04T09:46:18.901077101Z 12(608) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [To] type 3
2024-09-04T09:46:18.901080593Z 12(608) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=a87f9558cf5646d575962040dd7151c2-7dac3165
2024-09-04T09:46:18.901084412Z 12(608) DEBUG: <core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=29
2024-09-04T09:46:18.901088123Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [80]; uri=[sip:+35315220000@sip.frideo.eu]
2024-09-04T09:46:18.901092064Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (32)[<sip:+35315220000@sip.frideo.eu>], to tag (41)[a87f9558cf5646d575962040dd7151c2-7dac3165]
2024-09-04T09:46:18.901096019Z 12(608) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Call-ID] type 6
2024-09-04T09:46:18.901099325Z 12(608) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [CSeq] type 5
2024-09-04T09:46:18.901102700Z 12(608) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1244552063> <INVITE>
2024-09-04T09:46:18.901106343Z 12(608) DEBUG: siptrace [siptrace.c:2476]: siptrace_net_data_sent(): processing message mode 1
2024-09-04T09:46:18.901110013Z 12(608) DEBUG: siptrace [siptrace_hep.c:523]: pipport2su(): the port string is 5060
2024-09-04T09:46:18.901118717Z 12(608) DEBUG: siptrace [siptrace_hep.c:523]: pipport2su(): the port string is 5060
2024-09-04T09:46:18.901122582Z 12(608) DEBUG: <core> [core/proxy.c:267]: mk_proxy(): doing DNS lookup...
2024-09-04T09:46:18.901126610Z 12(608) DEBUG: siptrace [siptrace_hep.c:185]: trace_send_hep3_duplicate(): setting up the socket_info
2024-09-04T09:46:18.901130262Z 12(608) DEBUG: siptrace [siptrace_hep.c:200]: trace_send_hep3_duplicate(): send sock addr activated - find the sock_info
2024-09-04T09:46:18.901135032Z 12(608) DEBUG: siptrace [siptrace_hep.c:212]: trace_send_hep3_duplicate(): found send socket: [11.15.32.160] [11.15.32.160]
2024-09-04T09:46:18.901139112Z 12(608) DEBUG: tm [t_reply.c:2150]: relay_reply(): reply buffer sent out
2024-09-04T09:46:18.901142613Z 12(608) DEBUG: tm [t_funcs.c:133]: put_on_wait(): put T [0x7f71ed809c00] on wait
2024-09-04T09:46:19.399800335Z 13(609) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 2 (reply(status)) flags 1
2024-09-04T09:46:19.399831259Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:731]: parse_msg(): SIP Reply  (status):
2024-09-04T09:46:19.399837698Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:733]: parse_msg():  version: <SIP/2.0>
2024-09-04T09:46:19.399842134Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:735]: parse_msg():  status:  <408>
2024-09-04T09:46:19.399845627Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:737]: parse_msg():  reason:  <Request Timeout>
2024-09-04T09:46:19.399849115Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:19.399853254Z 13(609) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
2024-09-04T09:46:19.399858135Z 13(609) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-d8754z-cc2c63344f5218d>; state=6
2024-09-04T09:46:19.399863126Z 13(609) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 234, <received> = <11.15.32.1>; state=16
2024-09-04T09:46:19.399867609Z 13(609) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:19.399871749Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:19.399876346Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:19.399880943Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [From] type 4
2024-09-04T09:46:19.399887783Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [To] type 3
2024-09-04T09:46:19.399892837Z 13(609) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=a87f9558cf5646d575962040dd7151c2-7dac3165
2024-09-04T09:46:19.399897454Z 13(609) DEBUG: <core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=29
2024-09-04T09:46:19.399915013Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [80]; uri=[sip:+35315220000@sip.frideo.eu]
2024-09-04T09:46:19.399919958Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (32)[<sip:+35315220000@sip.frideo.eu>], to tag (41)[a87f9558cf5646d575962040dd7151c2-7dac3165]
2024-09-04T09:46:19.399924895Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Call-ID] type 6
2024-09-04T09:46:19.399929160Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [CSeq] type 5
2024-09-04T09:46:19.399933578Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1244552063> <INVITE>
2024-09-04T09:46:19.399938246Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Server] type 29
2024-09-04T09:46:19.399942467Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Content-Length] type 12
2024-09-04T09:46:19.399947450Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
2024-09-04T09:46:19.399952007Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
2024-09-04T09:46:19.400061813Z 13(609) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 2 (reply(status)) flags 1
2024-09-04T09:46:19.400069838Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:731]: parse_msg(): SIP Reply  (status):
2024-09-04T09:46:19.400074206Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:733]: parse_msg():  version: <SIP/2.0>
2024-09-04T09:46:19.400078786Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:735]: parse_msg():  status:  <408>
2024-09-04T09:46:19.400083315Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:737]: parse_msg():  reason:  <Request Timeout>
2024-09-04T09:46:19.400088091Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:19.400092383Z 13(609) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
2024-09-04T09:46:19.400097177Z 13(609) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-d8754z-cc2c63344f5218d>; state=6
2024-09-04T09:46:19.400101949Z 13(609) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 234, <received> = <11.15.32.1>; state=16
2024-09-04T09:46:19.400107022Z 13(609) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:19.400111158Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:19.400128599Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:19.400364321Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [From] type 4
2024-09-04T09:46:19.400374209Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [To] type 3
2024-09-04T09:46:19.400379147Z 13(609) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=a87f9558cf5646d575962040dd7151c2-7dac3165
2024-09-04T09:46:19.400383683Z 13(609) DEBUG: <core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=29
2024-09-04T09:46:19.400387891Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [80]; uri=[sip:+35315220000@sip.frideo.eu]
2024-09-04T09:46:19.400392398Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (32)[<sip:+35315220000@sip.frideo.eu>], to tag (41)[a87f9558cf5646d575962040dd7151c2-7dac3165]
2024-09-04T09:46:19.400396734Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Call-ID] type 6
2024-09-04T09:46:19.400400834Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [CSeq] type 5
2024-09-04T09:46:19.400404889Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1244552063> <INVITE>
2024-09-04T09:46:19.400409190Z 13(609) DEBUG: siptrace [siptrace.c:2476]: siptrace_net_data_sent(): processing message mode 1
2024-09-04T09:46:19.400413196Z 13(609) DEBUG: siptrace [siptrace_hep.c:523]: pipport2su(): the port string is 5060
2024-09-04T09:46:19.400417707Z 13(609) DEBUG: siptrace [siptrace_hep.c:523]: pipport2su(): the port string is 5060
2024-09-04T09:46:19.400422156Z 13(609) DEBUG: <core> [core/proxy.c:267]: mk_proxy(): doing DNS lookup...
2024-09-04T09:46:19.400430533Z 13(609) DEBUG: siptrace [siptrace_hep.c:185]: trace_send_hep3_duplicate(): setting up the socket_info
2024-09-04T09:46:19.400435395Z 13(609) DEBUG: siptrace [siptrace_hep.c:200]: trace_send_hep3_duplicate(): send sock addr activated - find the sock_info
2024-09-04T09:46:19.400440097Z 13(609) DEBUG: siptrace [siptrace_hep.c:212]: trace_send_hep3_duplicate(): found send socket: [11.15.32.160] [11.15.32.160]
2024-09-04T09:46:19.400444424Z 13(609) DEBUG: tm [t_reply.c:1723]: t_retransmit_reply(): reply retransmitted. buf=0x7f71ecdd39c0: SIP/2.0 4..., shmem=0x7f71ed80d040: SIP/2.0 4
2024-09-04T09:46:19.492543996Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:20.399774966Z 13(609) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 2 (reply(status)) flags 1
2024-09-04T09:46:20.399815161Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:731]: parse_msg(): SIP Reply  (status):
2024-09-04T09:46:20.399822394Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:733]: parse_msg():  version: <SIP/2.0>
2024-09-04T09:46:20.399844685Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:735]: parse_msg():  status:  <408>
2024-09-04T09:46:20.399849705Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:737]: parse_msg():  reason:  <Request Timeout>
2024-09-04T09:46:20.399852650Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:20.399855542Z 13(609) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
2024-09-04T09:46:20.399858675Z 13(609) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-d8754z-cc2c63344f5218d>; state=6
2024-09-04T09:46:20.399861636Z 13(609) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 234, <received> = <11.15.32.1>; state=16
2024-09-04T09:46:20.399866218Z 13(609) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:20.399870617Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:20.399874829Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:20.399879251Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [From] type 4
2024-09-04T09:46:20.399883684Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [To] type 3
2024-09-04T09:46:20.399888482Z 13(609) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=a87f9558cf5646d575962040dd7151c2-7dac3165
2024-09-04T09:46:20.399892905Z 13(609) DEBUG: <core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=29
2024-09-04T09:46:20.399896823Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [80]; uri=[sip:+35315220000@sip.frideo.eu]
2024-09-04T09:46:20.399900947Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (32)[<sip:+35315220000@sip.frideo.eu>], to tag (41)[a87f9558cf5646d575962040dd7151c2-7dac3165]
2024-09-04T09:46:20.399906119Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Call-ID] type 6
2024-09-04T09:46:20.399909925Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [CSeq] type 5
2024-09-04T09:46:20.399913881Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1244552063> <INVITE>
2024-09-04T09:46:20.399918556Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Server] type 29
2024-09-04T09:46:20.399922917Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Content-Length] type 12
2024-09-04T09:46:20.400205366Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:187]: get_hdr_field(): content_length=0
2024-09-04T09:46:20.400217218Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:91]: get_hdr_field(): found end of header
2024-09-04T09:46:20.400260400Z 13(609) DEBUG: <core> [core/parser/parse_fline.c:247]: parse_first_line(): first line type 2 (reply(status)) flags 1
2024-09-04T09:46:20.400267102Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:731]: parse_msg(): SIP Reply  (status):
2024-09-04T09:46:20.400271595Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:733]: parse_msg():  version: <SIP/2.0>
2024-09-04T09:46:20.400276150Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:735]: parse_msg():  status:  <408>
2024-09-04T09:46:20.400280349Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:737]: parse_msg():  reason:  <Request Timeout>
2024-09-04T09:46:20.400284701Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Via] type 1
2024-09-04T09:46:20.400289492Z 13(609) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 235, <rport> = <5060>; state=6
2024-09-04T09:46:20.400294326Z 13(609) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK-d8754z-cc2c63344f5218d>; state=6
2024-09-04T09:46:20.400316507Z 13(609) DEBUG: <core> [core/parser/parse_via.c:1312]: parse_via_param(): Found param type 234, <received> = <11.15.32.1>; state=16
2024-09-04T09:46:20.400321991Z 13(609) DEBUG: <core> [core/parser/parse_via.c:2663]: parse_via(): end of header reached, state=5
2024-09-04T09:46:20.400326423Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:591]: parse_headers(): Via found, flags=2
2024-09-04T09:46:20.400330494Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:593]: parse_headers(): this is the first via
2024-09-04T09:46:20.400334030Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [From] type 4
2024-09-04T09:46:20.400337801Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [To] type 3
2024-09-04T09:46:20.400341784Z 13(609) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=a87f9558cf5646d575962040dd7151c2-7dac3165
2024-09-04T09:46:20.400345830Z 13(609) DEBUG: <core> [core/parser/parse_addr_spec.c:904]: parse_addr_spec(): end of header reached, state=29
2024-09-04T09:46:20.400350070Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:173]: get_hdr_field(): <To> [80]; uri=[sip:+35315220000@sip.frideo.eu]
2024-09-04T09:46:20.400354037Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:176]: get_hdr_field(): to body (32)[<sip:+35315220000@sip.frideo.eu>], to tag (41)[a87f9558cf5646d575962040dd7151c2-7dac3165]
2024-09-04T09:46:20.400359254Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [Call-ID] type 6
2024-09-04T09:46:20.400372128Z 13(609) DEBUG: <core> [core/parser/parse_hname2.c:314]: parse_sip_header_name(): parsed header name [CSeq] type 5
2024-09-04T09:46:20.400377098Z 13(609) DEBUG: <core> [core/parser/msg_parser.c:154]: get_hdr_field(): cseq <CSeq>: <1244552063> <INVITE>
2024-09-04T09:46:20.400381970Z 13(609) DEBUG: siptrace [siptrace.c:2476]: siptrace_net_data_sent(): processing message mode 1
2024-09-04T09:46:20.400386345Z 13(609) DEBUG: siptrace [siptrace_hep.c:523]: pipport2su(): the port string is 5060
2024-09-04T09:46:20.400390497Z 13(609) DEBUG: siptrace [siptrace_hep.c:523]: pipport2su(): the port string is 5060
2024-09-04T09:46:20.400394211Z 13(609) DEBUG: <core> [core/proxy.c:267]: mk_proxy(): doing DNS lookup...
2024-09-04T09:46:20.400398310Z 13(609) DEBUG: siptrace [siptrace_hep.c:185]: trace_send_hep3_duplicate(): setting up the socket_info
2024-09-04T09:46:20.400402338Z 13(609) DEBUG: siptrace [siptrace_hep.c:200]: trace_send_hep3_duplicate(): send sock addr activated - find the sock_info
2024-09-04T09:46:20.400406163Z 13(609) DEBUG: siptrace [siptrace_hep.c:212]: trace_send_hep3_duplicate(): found send socket: [11.15.32.160] [11.15.32.160]
2024-09-04T09:46:20.400410392Z 13(609) DEBUG: tm [t_reply.c:1723]: t_retransmit_reply(): reply retransmitted. buf=0x7f71ecdd39c0: SIP/2.0 4..., shmem=0x7f71ed80d040: SIP/2.0 4
2024-09-04T09:46:20.493537417Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:21.494550160Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:21.899703029Z 12(608) DEBUG: tm [t_funcs.c:133]: put_on_wait(): put T [0x7f71ed809c00] on wait
2024-09-04T09:46:21.899737459Z 12(608) DEBUG: <core> [core/timer.c:555]: timer_add_safe(): timer_add called on an active timer 0x7f71ed809cb8 (0x7f71ecf612e0, 0x7f71ecf612e0), flags 201
2024-09-04T09:46:21.899744171Z 12(608) DEBUG: tm [t_funcs.c:156]: put_on_wait(): transaction 0x7f71ed809c00 already on wait
2024-09-04T09:46:22.495270800Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:23.496347626Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:23.899725303Z 13(609) DEBUG: tm [timer.c:642]: wait_handler(): finished transaction: 0x7f71ed809c00 (p:0x7f71ecfe0dc0/n:0x7f71ecfe0dc0)
2024-09-04T09:46:23.899763253Z 13(609) DEBUG: tm [h_table.c:133]: free_cell_helper(): freeing transaction 0x7f71ed809c00 from timer.c:651
2024-09-04T09:46:24.497123302Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:25.498187314Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:26.498604612Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:27.499667282Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:28.500508107Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:29.501142001Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1
2024-09-04T09:46:30.502164925Z 20(616) DEBUG: <core> [core/tcp_main.c:1726]: _tcpconn_find(): found connection by id: 1