I did do debug=3 and saw the logs but couldn't
figure out much. Here is the log for the appropriate ACK
received on websocket port. I've highlighted a few lines I felt
might be problematic:
DEBUG: <core> [tcp_read.c:1146]: ws_process_msg():
WebSocket Message:
[[>>>#012<81>þ#003ø´¶#037<8a>õõTªÇßo°<85><84>,¾ô<84>.¼<9a><87>-²<9a><8e>)¤<8c><8c>*º<82><83>$þÆ×qùÄÙmþ<89>Ã{ú<94>åVÚ<9b><84>1º¹¼IãÕ<8c>?Ùýæ0¸<9a><86>0Ýç<96>{ì<83>Ü~æ<86><85>sù<84>Ò1ãÚÀ~æÝÒ$èÆ×qéÜ<8b>e³Üñ+èÿ<8e>pÛÓÔjçñ<86>iÛ<8c>äKûöä+¾ú<8d>múÛÄk<87>¾ðmåÙ<8c>?¨þ×fïÇÞ=¶Çßo°<85><86>/º<84><86>.º<84><87>_íÜ×qþÝ<98>|åÙ<88>$þÕÑ"½ñýVÙÿ÷~áòñ-Ûî<84>UüÄòP<87>¾âp°<94><8a>lãÄ<8c>.¸<87><82>_íÜ×qþÝ<98>|åÙ<88>$þÕÑ"²ö<85>Y²<8c><81>T½ÿÀzç¹¼\åÚÂ~éÀ<8c>?¨þ×fïÇÞ=¶Çßo°<85><86>/º<84><86>.º<84><87>_�
�Ò<81>uëØ<84>,æÇ<86>{¤ÝØiëØß{±ÆÂ|ýÑÔ2èÆÓ~áÑÄ"äÛ<8d>|æÝÕt¸××sæ<89>Øp±ÀÄ~äÇÆpøÀ<8b>hù<8a><8d>4í<9a>Ùrë<9a>Åvú<99>ßr±<9f>Åvú<9a>ß|ï<8f>Ú~äÓÃ~íÑ<8b>=ïÚ<9a>yø<96>»#025ÉÕÚs§ýò%ª<86><87>/¾ÕÔ'³<99><80>&¿<82><9b>&è×<87>2¿<86><8e>z§Ö<87>'èÐ<8f>{¾Ö<85>.é¹¼\ÙÑÇ%ª<80><8e>'ªõõT<87>¾õpäÀÓqþ<99>úzäÓÂw°<94><86>#022<80>æÙjþÑ<8c>?¶Çßo°<86><87>)¤<85><84>'¤<8c><80>1³<8e><83>/¼<84><8d>sø<8f>ÅvúÙÚ*§ÛÃkèÛÃqî<8f>ÂmëÚÅoåÆÂ"ÿÐÆ!<87>¾û~ò<99>ðpøÃ×mîÇ<8c>?½<84>»#025ÚÆÙgó<99>÷jþÜÙmãÎ×kãÛØ%ªðßxïÇÂ?ÿÇÓmäÕÛz·<96>
<87>/º<84><86>/»<84><86>.¨<98>ÄzëØÛ"¨ÓÞ~äÀß1éÛÛ=¦ÚÙqéÑ<8b>=ß×Ò[ìØþWÛØúYÿÝþHÇ<84>ØI¡í<86>'þàÐFÆÓÁV¨<98>Ãmã<89><94>lãÄ<8c>.¸<87><82>_¸<85><80>1»<86><8e>1²<82><98>'°<81><86>)¿<8f>ÂmëÚÅoåÆÂ"ÿÐÆ=¦ÆÓlúÛØlï<89><94>{é<82><85>~º<83><81>y¾<82><8e>{¿<81>×&¾<8d>Ð)ëÕ<87>*ì<80>×z¼<82><83>=¦ÕÚxåÆßkâÙ<8b>RÎ<81>»#025ØÛÃkï<8e><96>#ùÝÆ%¸<85><80>1»<86><8e>1²<82><98>&°<8c><86>'º<8f>ÂmëÚÅoåÆÂ"ýÇ<8d>m¸<89>Ùq±ØÄ"åÚ<8d>yþÕÑ"½ñýVÙÿ÷~áòñ-Ûî<84>UüÄòP±Ú×k·ÍÓl´¹¼MåÁÂz°<94><8a>lãÄ<8c>-»<82><98>.¸<8c
><98>'¼<9a><8f>$ø<86><8b>pä<8f>Úm·ÛØ$ìÀ×x·<83>óTÃçý^ëßðX¸åì-ÀÂÆ[Å<8f>Ø~þ<89>Ïzù<8a>»#025ßÇÓm§õÑzäÀ<8c>?Ãù<9b>|æÝÓqþ<9b>ùRË<85><98>/ªÇßoÇø<83>2ü<85><98>-º<85><85>1º<87><98>-½¹¼PøÓ×qãÎ×kãÛØ%ªðÙjèÕØxå<94>âzæÑÕpç¹¼#022<80><<<]]
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: websocket
[ws_frame.c:346]: decode_and_validate_ws_frame(): decoding
WebSocket frame
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: websocket
[ws_frame.c:396]: decode_and_validate_ws_frame(): supported
non-control frame: 0x1
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/msg_parser.c:623]: parse_msg(): SIP
Request:
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/msg_parser.c:625]: parse_msg():
method: <ACK>
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/msg_parser.c:629]: parse_msg():
version: <SIP/2.0>
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/parse_via.c:1284]: parse_via_param():
Found param type 232, <branch> =
<z9hG4bK8oQgbumE0vQ8RTqBR44N>; state=6
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/parse_via.c:1284]: parse_via_param():
Found param type 235, <rport> = <n/a>; state=17
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/parse_via.c:2672]: parse_via(): end of
header reached, state=5
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/msg_parser.c:513]: parse_headers():
parse_headers: Via found, flags=2
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/msg_parser.c:515]: parse_headers():
parse_headers: this is the first via
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [receive.c:149]: receive_msg(): After
parse_msg...
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [receive.c:190]: receive_msg(): preparing to
run routing scripts...
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: sl
[sl_funcs.c:396]: sl_filter_ACK(): DEBUG : sl_filter_ACK: to
late to be a local ACK!
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/parse_to.c:176]: parse_to_param():
DEBUG: add_param: tag=8B3F887K7Kvem
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/parse_to.c:799]: parse_to(): end of
header reached, state=29
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/msg_parser.c:190]: get_hdr_field():
DEBUG: get_hdr_field: <To> [41]; uri=[
sip:1234@ghanti.com]
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/msg_parser.c:192]: get_hdr_field():
DEBUG: to body [<
sip:1234@ghanti.com>]
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/msg_parser.c:170]: get_hdr_field():
get_hdr_field: cseq <CSeq>: <488> <ACK>
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/msg_parser.c:204]: get_hdr_field():
DEBUG: get_hdr_body : content_length=0
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: maxfwd
[mf_funcs.c:85]: is_maxfwd_present(): value = 70
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: maxfwd
[maxfwd.c:161]: process_maxfwd_header(): value 70 decreased
to 16
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/msg_parser.c:106]: get_hdr_field():
found end of header
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/parse_to.c:176]: parse_to_param():
DEBUG: add_param: tag=7EKISKAakFG2QZ2JvpDO
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [parser/parse_to.c:799]: parse_to(): end of
header reached, state=29
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: sanity
[mod_sanity.c:255]: w_sanity_check(): sanity checks result:
1
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: INFO:
<script>: Request Method is ACK
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: nathelper
[nathelper.c:888]: add_contact_alias_0_f(): contact uri host
is not an ip address
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: nathelper
[nathelper.c:965]: add_contact_alias_0_f(): adding param
<;alias=203.153.53.166~59841~5>
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: INFO:
<script>: Inside NATDETECT
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: nathelper
[nathelper.c:888]: add_contact_alias_0_f(): contact uri host
is not an ip address
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: nathelper
[nathelper.c:965]: add_contact_alias_0_f(): adding param
<;alias=203.153.53.166~59841~5>
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: siputils
[checks.c:106]: has_totag(): totag found
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: rr
[loose.c:89]: is_preloaded(): is_preloaded: No
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [socket_info.c:589]: grep_sock_info():
grep_sock_info - checking if host==us: 12==12 &&
[126.128.68.8] == [126.128.68.9]
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [socket_info.c:593]: grep_sock_info():
grep_sock_info - checking if port 5060 (advertise 0) matches
port 5065
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [socket_info.c:589]: grep_sock_info():
grep_sock_info - checking if host==us: 12==12 &&
[126.128.68.8] == [126.128.68.9]
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [socket_info.c:593]: grep_sock_info():
grep_sock_info - checking if port 5060 (advertise 0) matches
port 5065
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [socket_info.c:589]: grep_sock_info():
grep_sock_info - checking if host==us: 12==12 &&
[126.128.68.8] == [126.128.68.9]
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [socket_info.c:593]: grep_sock_info():
grep_sock_info - checking if port 8080 (advertise 0) matches
port 5065
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [forward.c:462]: check_self(): check_self: host
!= me
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [socket_info.c:589]: grep_sock_info():
grep_sock_info - checking if host==us: 12==12 &&
[126.128.68.9] == [126.128.68.9]
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [socket_info.c:593]: grep_sock_info():
grep_sock_info - checking if port 5060 (advertise 0) matches
port 5060
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: rr
[loose.c:871]: after_loose(): Next URI is a loose router
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: siputils
[checks.c:106]: has_totag(): totag found
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: rr
[loose.c:974]: check_route_param(): params are
<;lr;sipml5-outbound;transport=udp>
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: INFO:
<script>: Inside Natmanage ACK
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: siputils
[checks.c:106]: has_totag(): totag found
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: tm
[t_lookup.c:1395]: t_newtran(): DEBUG: t_newtran: msg id=8 ,
global msg id=7 , T on entrance=(nil)
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: tm
[t_lookup.c:534]: t_lookup_request(): t_lookup_request:
start searching: hash=60000, isACK=1
un 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: tm
[t_lookup.c:492]: matching_3261(): DEBUG: RFC3261
transaction matching failed
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: tm
[t_lookup.c:716]: t_lookup_request(): DEBUG:
t_lookup_request: no transaction found
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: tm
[t_funcs.c:311]: t_relay_to(): SER: forwarding ACK
statelessly
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: WARNING:
<core> [msg_translator.c:2499]: via_builder():
TCP/TLS connection (id: 0) for WebSocket could not be
found
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: ERROR:
<core> [msg_translator.c:1725]:
build_req_buf_from_sip_req(): could not create Via header
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: ERROR:
<core> [forward.c:607]: forward_request(): ERROR:
forward_request: building failed
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: ERROR: sl
[sl_funcs.c:371]: sl_reply_error(): ERROR: sl_reply_error
used: I'm terribly sorry, server error occurred (1/SL)
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [usr_avp.c:644]: destroy_avp_list():
DEBUG:destroy_avp_list: destroying list (nil)
Jun 23 18:45:46
/usr/local/ghanti-ko/sbin/kamailio[22879]: last message
repeated 5 times
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [xavp.c:447]: xavp_destroy_list(): destroying
xavp list (nil)
Jun 23 18:45:46 v9
/usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
<core> [receive.c:293]: receive_msg(): receive_msg:
cleaning up
Thanks for all the help.