I've repeated the test with DEBUG level logging.
The logs seem to indicate that whatever this problem is, it
happens when trying to relay (using t_relay()) when outbound is
in use. Here are the detailed logs:
16(1547) DEBUG: rr [loose.c:86]: is_preloaded():
is_preloaded: Yes
16(1547) DEBUG: <core> [socket_info.c:583]:
grep_sock_info(): grep_sock_info - checking if host==us:
27==11 && [
edge01-int.crocodilertc.net]
== [10.112.7.76]
16(1547) DEBUG: <core> [socket_info.c:587]:
grep_sock_info(): grep_sock_info - checking if port 5060
(advertise 5060) matches port 5080
16(1547) DEBUG: <core> [socket_info.c:583]:
grep_sock_info(): grep_sock_info - checking if host==us:
27==11 && [
edge01-int.crocodilertc.net]
== [10.112.7.76]
16(1547) DEBUG: <core> [socket_info.c:587]:
grep_sock_info(): grep_sock_info - checking if port 80
(advertise 80) matches port 5080
16(1547) DEBUG: <core> [socket_info.c:583]:
grep_sock_info(): grep_sock_info - checking if host==us:
27==11 && [
edge01-int.crocodilertc.net]
== [10.112.7.76]
16(1547) DEBUG: <core> [socket_info.c:587]:
grep_sock_info(): grep_sock_info - checking if port 5060
(advertise 5060) matches port 5080
16(1547) DEBUG: <core> [socket_info.c:583]:
grep_sock_info(): grep_sock_info - checking if host==us:
27==11 && [
edge01-int.crocodilertc.net]
== [10.112.7.76]
16(1547) DEBUG: <core> [socket_info.c:587]:
grep_sock_info(): grep_sock_info - checking if port 5080
(advertise 5080) matches port 5080
16(1547) DEBUG: rr [loose.c:525]: process_outbound():
"incoming" request found. Using flow-token forrouting
16(1547) DEBUG: <core> [parser/msg_parser.c:106]:
get_hdr_field(): found end of header
16(1547) DEBUG: rr [loose.c:181]: find_next_route(): No
next Route HF found
16(1547) DEBUG: rr [loose.c:809]: after_loose(): No next
URI found
16(1547) DEBUG: tm [t_lookup.c:1372]: t_newtran(): DEBUG:
t_newtran: msg id=1 , global msg id=1 , T on entrance=(nil)
16(1547) DEBUG: tm [t_lookup.c:527]: t_lookup_request():
t_lookup_request: start searching: hash=4829, isACK=0
16(1547) DEBUG: tm [t_lookup.c:485]: matching_3261():
DEBUG: RFC3261 transaction matching failed
16(1547) DEBUG: tm [t_lookup.c:709]: t_lookup_request():
DEBUG: t_lookup_request: no transaction found
16(1547) DEBUG: tm [t_hooks.c:374]:
run_reqin_callbacks_internal(): DBG: trans=0x7fe2a1af2080,
callback type 1, id 0 entered
16(1547) DEBUG: <core> [md5utils.c:67]:
MD5StringArray(): DEBUG: MD5 calculated:
86424f366665cacef83c4e082d9c7167
16(1547) ERROR: <core> [resolve.c:1700]:
sip_hostport2su(): ERROR: sip_hostport2su: could not resolve
hostname: "90.152.0.102"
16(1547) ERROR: tm [ut.h:337]: uri2dst2(): failed to
resolve "90.152.0.102"
16(1547) ERROR: tm [t_fwd.c:1772]: t_forward_nonack():
ERROR: t_forward_nonack: failure to add branches
16(1547) DEBUG: tm [t_funcs.c:357]: t_relay_to():
ERROR:tm:t_relay_to: t_forward_nonack returned error
16(1547) DEBUG: tm [t_funcs.c:374]: t_relay_to(): -478
error reply generation delayed
16(1547) DEBUG: tm [t_lookup.c:1071]: t_check_msg():
DEBUG: t_check_msg: msg id=1 global id=1 T
start=0x7fe2a1af2080
16(1547) DEBUG: tm [t_lookup.c:1143]: t_check_msg():
DEBUG: t_check_msg: T already found!
16(1547) DEBUG: <core> [mem/shm_mem.c:111]:
_shm_resize(): WARNING:vqm_resize: resize(0) called
16(1547) DEBUG: tm [t_reply.c:1667]:
cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR
timers reset
16(1547) DEBUG: <core> [tcp_main.c:2320]:
tcpconn_send_put(): tcp_send: send from reader (1547 (16)),
reusing fd
16(1547) DEBUG: <core> [tcp_main.c:2556]:
tcpconn_do_send(): tcp_send: sending...
16(1547) DEBUG: <core> [tcp_main.c:2590]:
tcpconn_do_send(): tcp_send: after real write: c=
0x7fe2a19f1d70 n=651 fd=8
16(1547) DEBUG: <core> [tcp_main.c:2591]:
tcpconn_do_send(): tcp_send: buf=
SIP/2.0 430 Flow Failed^M
Does anyone know of any recent TM or resolver changes that
would affect this?