Yes, I think its DNS related because the callflows look perfect when both my
DNS servers are up and running. This scenario only occurs when the primary dns
server is offline. I thought maybe my debug trace would tell more of the story.
Sorry I dont have a ngrep trace.
<< primary dns is offline; assuming res_search() considers the secondary in
resolv.conf >>Jan 10 20:55:20 www openser[21124]: get_record:
lookup(5934.rdtw1.qa2.l1.voiplabs.net, 35) failedJan 10 20:55:20 www
openser[21124]: DEBUG:sip_resolvehost2: no valid NAPTR record found for
5934.rdtw1.qa2.l1.voiplabs.net, trying direct SRV lookup...Jan 10 20:55:20 www
openser[21346]: get_record: lookup(5934.rdtw1.qa2.l1.voiplabs.net, 35)
failedJan 10 20:55:20 www openser[21346]: DEBUG:sip_resolvehost2: no valid
NAPTR record found for 5934.rdtw1.qa2.l1.voiplabs.net, trying direct SRV
lookup...Jan 10 20:55:20 www openser[21140]: is_from_user_enum(): order 100,
pref 100, flen 1, flags 'u', slen 7, services 'SIP+E2U', rlen 43, regexp
'!^(.*)$!sip:[EMAIL PROTECTED]'Jan 10 20:55:20 www openser[21140]:
reg_replace(): pattern: '^(.*)$', replacement: 'sip:[EMAIL PROTECTED]', string:
'+14556660002'Jan 10 20:55:20 www openser[21140]: is_from_user_enum(): resulted
in replacement: 'sip:[EMAIL PROTECTED]'Jan 10 20:55:20 www openser[21140]:
DEBUG:sip_resolvehost2: no port, no proto -> do NAPTR lookup!Jan 10 20:55:21
www openser[21233]: get_record: lookup(5934.rdtw1.qa2.l1.voiplabs.net, 35)
failedJan 10 20:55:21 www openser[21233]: DEBUG:sip_resolvehost2: no valid
NAPTR record found for 5934.rdtw1.qa2.l1.voiplabs.net, trying direct SRV
lookup...<<processing 200 OK (invite) for the first time >>Jan 10 20:55:22 www
openser[21124]: SIP Reply (status):Jan 10 20:55:22 www openser[21124]:
version: <SIP/2.0>Jan 10 20:55:22 www openser[21124]: status: <200>Jan 10
20:55:22 www openser[21124]: reason: <OK>Jan 10 20:55:22 www openser[21124]:
parse_headers: flags=2Jan 10 20:55:22 www openser[21124]: Found param type 232,
<branch> = <z9hG4bK7d34.d8cbc746.0>; state=16Jan 10 20:55:22 www
openser[21124]: end of header reached, state=5Jan 10 20:55:22 www
openser[21124]: parse_headers: Via found, flags=2Jan 10 20:55:22 www
openser[21124]: parse_headers: this is the first viaJan 10 20:55:22 www
openser[21124]: After parse_msg...Jan 10 20:55:22 www openser[21124]:
forward_reply: found module tm, passing reply to itJan 10 20:55:22 www
openser[21124]: DEBUG: t_check: msg id=19 global id=18 T start=0xffffffffJan 10
20:55:22 www openser[21124]: parse_headers: flags=22Jan 10 20:55:22 www
openser[21124]: Found param type 232, <branch> = <z9hG4bK175-64.101.130.210>;
state=16Jan 10 20:55:22 www openser[21124]: end of header reached, state=5Jan
10 20:55:22 www openser[21124]: parse_headers: Via found, flags=22Jan 10
20:55:22 www openser[21124]: parse_headers: this is the second viaJan 10
20:55:22 www openser[21124]: DEBUG: add_param: tag=35Jan 10 20:55:22 www
openser[21124]: DEBUG:parse_to:end of header reached, state=29Jan 10 20:55:22
www openser[21124]: DBUG:parse_to: display={"18001033799"}, ruri={sip:[EMAIL
PROTECTED] 10 20:55:22 www openser[21124]: DEBUG: get_hdr_field: <To> [64];
uri=[sip:[EMAIL PROTECTED] Jan 10 20:55:22 www openser[21124]: DEBUG: to body
["18001033799" <sip:[EMAIL PROTECTED]>]Jan 10 20:55:22 www openser[21124]:
get_hdr_field: cseq <CSeq>: <1> <INVITE>Jan 10 20:55:22 www openser[21124]:
parse_headers: flags=8Jan 10 20:55:22 www openser[21124]: DEBUG:
t_reply_matching: hash 17367 label 1685896333 branch 0Jan 10 20:55:22 www
openser[21124]: DEBUG:tm:REF_UNSAFE: after is 1Jan 10 20:55:22 www
openser[21124]: DEBUG: t_reply_matching: reply matched (T=0x283fe3a8)!Jan 10
20:55:22 www openser[21124]: parse_headers: flags=8Jan 10 20:55:22 www
openser[21124]: DBG: trans=0x283fe3a8, callback type 2, id 0 enteredJan 10
20:55:22 www openser[21124]: parse_headers: flags=8Jan 10 20:55:22 www
openser[21124]: DEBUG: t_check: msg id=19 global id=19 T end=0x283fe3a8Jan 10
20:55:22 www openser[21124]: DEBUG:tm:reply_received: org. status uas=180,
uac[0]=180 local=0 is_invite=1)Jan 10 20:55:22 www openser[21124]:
DEBUG:tm:t_should_relay_response: T_code=180, new_code=200Jan 10 20:55:22 www
openser[21124]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0Jan 10 20:55:22
www openser[21124]: old size: 844, new size: 783Jan 10 20:55:22 www
openser[21124]: build_res_from_sip_res: copied size: orig:289, new: 228, rest:
555 msg= SIP/2.0 200 OK^M Record-Route:
<sip:10.88.128.76;lr;ftag=64.101.130.210>^M Record-Route:
<sip:10.88.128.77;lr;ftag=64.101.130.210>^M Record-Route:
<sip:10.88.128.74;lr;ftag=64.101.130.210>^M Record-Route:
<sip:64.101.130.210:5062>^M Via: SIP/2.0/UDP
64.101.130.210:5062;branch=z9hG4bK175-64.101.130.210^M From: "14556660002"
<sip:[EMAIL PROTECTED]>;tag=64.101.130.210^M To: "18001033799" <sip:[EMAIL
PROTECTED]>;tag=35^M Call-ID: [EMAIL PROTECTED] CSeq: 1 INVITE^M Max-Forwards:
70^M Content-Length: 145^M Contact: "18001033799" <sip:[EMAIL
PROTECTED]:6001>^M Content-Type: application/sdp^M ^M v=0^M o=user1 53655765
2353687637 IN IP4 10.88.129.252^M s=SIP Call^M c=IN IP4 10.88.129.252^M t=0 0^M
m=audio 10800 RTP/AVP 0^M a=rtpmap:0 PCMU/8000^M Jan 10 20:55:22 www
openser[21124]: DEBUG: update_totag_set: new totag Jan 10 20:55:22 www
openser[21124]: DEBUG: add_to_tail_of_timer[2]: 0x283fe3f0Jan 10 20:55:22 www
openser[21124]: DEBUG:tm:relay_reply: sent buf=0x81351c8: SIP/2.0 2...,
shmem=0x283fe090: SIP/2.0 2Jan 10 20:55:22 www openser[21124]: DBG:
trans=0x283fe3a8, callback type 128, id 0 enteredJan 10 20:55:22 www
openser[21124]: ACC: transaction answered: method=INVITE, i-uri=sip:[EMAIL
PROTECTED], o-uri=sip:[EMAIL PROTECTED]:5060, [EMAIL PROTECTED],
from="14556660002" <sip:[EMAIL PROTECTED]>;tag=64.101.130.210, code=200,
uid=n/a, fromtag=64.101.130.210, fromuri=sip:[EMAIL PROTECTED],
fromuri=sip:[EMAIL PROTECTED], fromuser=+14556660002,
fromdomain=5934.rdtw1.qa2.l1.voiplabs.net, to="18001033799" <sip:[EMAIL
PROTECTED]>;tag=35, totag=35, touri=sip:[EMAIL PROTECTED], touser=+18001033799,
userpart=+18001033799, domain=rdtw1.qa2.l1.voiplabs.netJan 10 20:55:22 www
openser[21124]: DEBUG: cleanup_uac_timers: RETR/FR timers resetJan 10 20:55:22
www openser[21124]: DEBUG:tm:UNREF_UNSAFE: after is 0Jan 10 20:55:22 www
openser[21124]: DEBUG:destroy_avp_list: destroying list 0x0Jan 10 20:55:22 www
openser[21124]: receive_msg: cleaning up<< processing ACK from orig >>Jan 10
20:55:22 www openser[21124]: SIP Request:Jan 10 20:55:22 www openser[21124]:
method: <ACK>Jan 10 20:55:22 www openser[21124]: uri: <sip:[EMAIL
PROTECTED]>Jan 10 20:55:22 www openser[21124]: version: <SIP/2.0>Jan 10
20:55:22 www openser[21124]: parse_headers: flags=2Jan 10 20:55:22 www
openser[21124]: end of header reached, state=5Jan 10 20:55:22 www
openser[21124]: parse_headers: Via found, flags=2Jan 10 20:55:22 www
openser[21124]: parse_headers: this is the first viaJan 10 20:55:22 www
openser[21124]: After parse_msg...Jan 10 20:55:22 www openser[21124]: preparing
to run routing scripts...Jan 10 20:55:22 www openser[21124]: DEBUG :
sl_filter_ACK: to late to be a local ACK!Jan 10 20:55:22 www openser[21124]:
parse_headers: flags=100Jan 10 20:55:22 www openser[21124]: DEBUG: add_param:
tag=35Jan 10 20:55:22 www openser[21124]: DEBUG:parse_to:end of header reached,
state=29Jan 10 20:55:22 www openser[21124]: DBUG:parse_to:
display={"18001033799"}, ruri={sip:[EMAIL PROTECTED] 10 20:55:22 www
openser[21124]: DEBUG: get_hdr_field: <To> [64]; uri=[sip:[EMAIL PROTECTED] Jan
10 20:55:22 www openser[21124]: DEBUG: to body ["18001033799" <sip:[EMAIL
PROTECTED]>]Jan 10 20:55:22 www openser[21124]: get_hdr_field: cseq <Cseq>: <2>
<ACK>Jan 10 20:55:22 www openser[21124]: DEBUG:maxfwd:is_maxfwd_present: value
= 70 Jan 10 20:55:22 www openser[21124]: parse_headers: flags=200Jan 10
20:55:22 www openser[21124]: is_preloaded: NoJan 10 20:55:22 www
openser[21124]: grep_sock_info - checking if host==us: 13==12 &&
[10.88.129.253] == [10.88.128.74]Jan 10 20:55:22 www openser[21124]:
grep_sock_info - checking if port 5060 matches port 5060Jan 10 20:55:22 www
openser[21124]: check_self: host != meJan 10 20:55:22 www openser[21124]:
grep_sock_info - checking if host==us: 12==12 && [10.88.128.74] ==
[10.88.128.74]Jan 10 20:55:22 www openser[21124]: grep_sock_info - checking if
port 5060 matches port 5060Jan 10 20:55:22 www openser[21124]: after_loose:
Topmost route URI: 'sip:10.88.128.74;lr;ftag=64.101.130.210' is meJan 10
20:55:22 www openser[21124]: after_loose: URI to be processed:
'sip:10.88.128.77;lr;ftag=64.101.130.210'Jan 10 20:55:22 www openser[21124]:
after_loose: Next URI is a loose routerJan 10 20:55:22 www openser[21124]:
DEBUG: t_newtran: msg id=20 , global msg id=19 , T on entrance=0xffffffffJan 10
20:55:22 www openser[21124]: parse_headers: flags=ffffffffffffffffJan 10
20:55:22 www openser[21124]: DEBUG: get_hdr_body : content_length=0Jan 10
20:55:22 www openser[21124]: found end of headerJan 10 20:55:22 www
openser[21124]: parse_headers: flags=78Jan 10 20:55:22 www openser[21124]:
t_lookup_request: start searching: hash=17364, isACK=1Jan 10 20:55:22 www
openser[21124]: DEBUG: proceeding to pre-RFC3261 transaction matchingJan 10
20:55:22 www openser[21124]: DEBUG: t_lookup_request: no transaction foundJan
10 20:55:22 www openser[21124]: DEBUG:tm:t_relay: forwarding ACKJan 10 20:55:22
www openser[21124]: DEBUG: mk_proxy: doing DNS lookup...Jan 10 20:55:22 www
openser[21124]: check_via_address(64.101.130.210, 64.101.130.210, 0)Jan 10
20:55:22 www openser[21124]: Sending: ACK sip:[EMAIL PROTECTED] SIP/2.0^M Via:
SIP/2.0/UDP 10.88.128.74;branch=0^M Via: SIP/2.0/UDP 64.101.130.210:5062^M
From: "14556660002" <sip:[EMAIL PROTECTED]>;tag=64.101.130.210^M To:
"18001033799" <sip:[EMAIL PROTECTED]>;tag=35^M Call-ID: [EMAIL PROTECTED] Cseq:
2 ACK^M Contact: "14556660002" <sip:[EMAIL PROTECTED]>^M Max-Forwards: 69^M
Record-Route: <sip:64.101.130.210:5062>^M Route:
<sip:10.88.128.77;lr;ftag=64.101.130.210>,<sip:10.88.128.76;lr;ftag=64.101.130.210>,"18001033799"
<sip:[EMAIL PROTECTED]:6001>^M Content-Length: 0^M ^M .Jan 10 20:55:22 www
openser[21124]: orig. len=608, new_len=605, proto=1Jan 10 20:55:22 www
openser[21124]: DEBUG:destroy_avp_list: destroying list 0x0Jan 10 20:55:22 www
openser[21124]: receive_msg: cleaning up<< strange behavior starts here ...
>>Jan 10 20:55:22 www openser[21346]: DEBUG:do_srv_lookup:
SRV(_sip._udp.5934.rdtw1.qa2.l1.voiplabs.net) =
proxy.5934.rdtw1.qa2.l1.voiplabs.net:5060Jan 10 20:55:22 www openser[21346]:
rdtw1.qa2.l1.voiplabs.net-outbound: time_t=1168484116 ^LINE=180
^FILE=/var/local/ser/ROUTLET/config.pre [EMAIL PROTECTED] ^cseq=1
^contact="14556660002" <sip:[EMAIL PROTECTED]> ^from=sip:[EMAIL PROTECTED]
^fromtag=64.101.130.210 ^to=sip:[EMAIL PROTECTED] ^totag=<null> ^method=INVITE
^ruri=sip:[EMAIL PROTECTED] ^messageid=8^remark=sJan 10 20:55:22 www
openser[21346]: rdtw1.qa2.l1.voiplabs.net-RECORDROUTE: time_t=1168484116
^LINE=180 ^FILE=/var/local/ser/ROUTLET/config.pre [EMAIL PROTECTED] ^cseq=1
^contact="14556660002" <sip:[EMAIL PROTECTED]> ^from=sip:[EMAIL PROTECTED]
^fromtag=64.101.130.210 ^to=sip:[EMAIL PROTECTED] ^totag=<null> ^method=INVITE
^ruri=sip:[EMAIL PROTECTED]:5060
^messageid=8^remark=rdtw1.qa2.l1.voiplabs.netJan 10 20:55:22 www
openser[21346]: DEBUG: t_newtran: msg id=8 , global msg id=7 , T on
entrance=0xffffffffJan 10 20:55:22 www openser[21346]: parse_headers:
flags=ffffffffffffffffJan 10 20:55:22 www openser[21346]: parse_headers:
flags=78Jan 10 20:55:22 www openser[21346]: t_lookup_request: start searching:
hash=17367, isACK=0Jan 10 20:55:22 www openser[21346]: DEBUG: RFC3261
transaction matched, tid=175-64.101.130.210Jan 10 20:55:22 www openser[21346]:
DEBUG:tm:REF_UNSAFE: after is 1Jan 10 20:55:22 www openser[21346]: DEBUG:
t_lookup_request: transaction found (T=0x283fe3a8)<< about to reTX the 200 OK
(invite) *even though we just finished processing ACK* >>Jan 10 20:55:22 www
openser[21346]: DEBUG:tm:t_retransmit_reply: buf=0x28229b40: SIP/2.0 2...,
shmem=0x283fe090: SIP/2.0 2 ! ! ! ! ! ! ! !!!!!!!!Jan 10 20:55:22 www
openser[21346]: DEBUG:tm:UNREF_UNSAFE: after is 0Jan 10 20:55:22 www
openser[21346]: DEBUG:destroy_avp_list: destroying list 0x0Jan 10 20:55:22 www
openser[21346]: receive_msg: cleaning up<< orig sends another ACK; to be
expected since we just reTX the 200 OK >>Jan 10 20:55:22 www openser[21124]:
SIP Request:Jan 10 20:55:22 www openser[21124]: method: <ACK>Jan 10 20:55:22
www openser[21124]: uri: <sip:[EMAIL PROTECTED]>Jan 10 20:55:22 www
openser[21124]: version: <SIP/2.0>Jan 10 20:55:22 www openser[21124]:
parse_headers: flags=2Jan 10 20:55:22 www openser[21124]: end of header
reached, state=5Jan 10 20:55:22 www openser[21124]: parse_headers: Via found,
flags=2Jan 10 20:55:22 www openser[21124]: parse_headers: this is the first
viaJan 10 20:55:22 www openser[21124]: After parse_msg...Jan 10 20:55:22 www
openser[21124]: preparing to run routing scripts...Jan 10 20:55:22 www
openser[21124]: DEBUG : sl_filter_ACK: to late to be a local ACK!Jan 10
20:55:22 www openser[21124]: parse_headers: flags=100Jan 10 20:55:22 www
openser[21124]: DEBUG: add_param: tag=35Jan 10 20:55:22 www openser[21124]:
DEBUG:parse_to:end of header reached, state=29Jan 10 20:55:22 www
openser[21124]: DBUG:parse_to: display={"18001033799"}, ruri={sip:[EMAIL
PROTECTED] 10 20:55:22 www openser[21124]: DEBUG: get_hdr_field: <To> [64];
uri=[sip:[EMAIL PROTECTED] Jan 10 20:55:22 www openser[21124]: DEBUG: to body
["18001033799" <sip:[EMAIL PROTECTED]>]Jan 10 20:55:22 www openser[21124]:
get_hdr_field: cseq <Cseq>: <2> <ACK>Jan 10 20:55:22 www openser[21124]:
DEBUG:maxfwd:is_maxfwd_present: value = 70 Jan 10 20:55:22 www openser[21124]:
parse_headers: flags=200Jan 10 20:55:22 www openser[21124]: is_preloaded: NoJan
10 20:55:22 www openser[21124]: grep_sock_info - checking if host==us: 13==12
&& [10.88.129.253] == [10.88.128.74]Jan 10 20:55:22 www openser[21124]:
grep_sock_info - checking if port 5060 matches port 5060Jan 10 20:55:22 www
openser[21124]: check_self: host != meJan 10 20:55:22 www openser[21124]:
grep_sock_info - checking if host==us: 12==12 && [10.88.128.74] ==
[10.88.128.74]Jan 10 20:55:22 www openser[21124]: grep_sock_info - checking if
port 5060 matches port 5060Jan 10 20:55:22 www openser[21124]: after_loose:
Topmost route URI: 'sip:10.88.128.74;lr;ftag=64.101.130.210' is meJan 10
20:55:22 www openser[21124]: after_loose: URI to be processed:
'sip:10.88.128.77;lr;ftag=64.101.130.210'Jan 10 20:55:22 www openser[21124]:
after_loose: Next URI is a loose routerJan 10 20:55:22 www openser[21124]:
DEBUG: t_newtran: msg id=21 , global msg id=20 , T on entrance=0xffffffffJan 10
20:55:22 www openser[21124]: parse_headers: flags=ffffffffffffffffJan 10
20:55:22 www openser[21124]: DEBUG: get_hdr_body : content_length=0Jan 10
20:55:22 www openser[21124]: found end of headerJan 10 20:55:22 www
openser[21124]: parse_headers: flags=78Jan 10 20:55:22 www openser[21124]:
t_lookup_request: start searching: hash=17364, isACK=1Jan 10 20:55:22 www
openser[21124]: DEBUG: proceeding to pre-RFC3261 transaction matchingJan 10
20:55:22 www openser[21124]: DEBUG: t_lookup_request: no transaction foundJan
10 20:55:22 www openser[21124]: DEBUG:tm:t_relay: forwarding ACKJan 10 20:55:22
www openser[21124]: DEBUG: mk_proxy: doing DNS lookup...Jan 10 20:55:22 www
openser[21124]: check_via_address(64.101.130.210, 64.101.130.210, 0)Jan 10
20:55:22 www openser[21124]: Sending: ACK sip:[EMAIL PROTECTED] SIP/2.0^M Via:
SIP/2.0/UDP 10.88.128.74;branch=0^M Via: SIP/2.0/UDP 64.101.130.210:5062^M
From: "14556660002" <sip:[EMAIL PROTECTED]>;tag=64.101.130.210^M To:
"18001033799" <sip:[EMAIL PROTECTED]>;tag=35^M Call-ID: [EMAIL PROTECTED] Cseq:
2 ACK^M Contact: "14556660002" <sip:[EMAIL PROTECTED]>^M Max-Forwards: 69^M
Record-Route: <sip:64.101.130.210:5062>^M Route:
<sip:10.88.128.77;lr;ftag=64.101.130.210>,<sip:10.88.128.76;lr;ftag=64.101.130.210>,"18001033799"
<sip:[EMAIL PROTECTED]:6001>^M Content-Length: 0^M ^M .Jan 10 20:55:22 www
openser[21124]: orig. len=608, new_len=605, proto=1Jan 10 20:55:22 www
openser[21124]: DEBUG:destroy_avp_list: destroying list 0x0Jan 10 20:55:22 www
openser[21124]: receive_msg: cleaning upJan 10 20:55:23 www openser[21376]:
DEBUG: timer routine:1,tl=0x283fe4d4 next=0x0Jan 10 20:55:23 www
openser[21376]: DEBUG: timer routine:4,tl=0x283fe4c4 next=0x0<< repeat reTX 200
OK (invite) / ACK several times >>Any Ideas?Will> Date: Thu, 11 Jan 2007
17:23:10 +0100> From: [EMAIL PROTECTED]> To: [EMAIL PROTECTED]> CC:
[email protected]> Subject: Re: [Users] using multiple DNS servers> > Will Quan
wrote:> > I have a primary and secondary dns server setup in resolv.conf, with>
> a timeout option of 1 second.The idea is when the primary fails, my> >
secondary server picks up the workload.When openser is running, and> > primary
dns is down, I am seeing several re-transmissions of 200 OK> > (invite) to my
originator *after* openser has finished processing> > ACK. I was thinking the
final responses would stop reTX after the ACK> > was t_relayed. Have you seen
such behavior? And better yet- Is there> > a solution for this?Thanks, Will> >
Are you sure this problem is related to DNS failover?> > regards> klaus> > > >
> > > ------------------------------------------------------------------------>
> > > > > _______________________________________________ Users mailing list >
> [email protected] http://openser.org/cgi-bin/mailman/listinfo/users> > > -- >
Klaus Darilion> nic.at> _______________________________________________
Users mailing list
[email protected]
http://openser.org/cgi-bin/mailman/listinfo/users
