RE: [Users] using multiple DNS servers

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:\1@5934.rdtw1.qa2.l1.voiplabs.net!'Jan 10 20:55:20 www openser[21140]: reg_replace(): pattern: '^(.*)$', replacement: 'sip:\1@5934.rdtw1.qa2.l1.voiplabs.net', string: '+14556660002'Jan 10 20:55:20 www openser[21140]: is_from_user_enum(): resulted in replacement: 'sip:+14556660002@5934.rdtw1.qa2.l1.voiplabs.net'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:+18001033799@rdtw1.qa2.l1.voiplabs.net}Jan 10 20:55:22 www openser[21124]: DEBUG: get_hdr_field: <To> [64]; uri=[sip:+18001033799@rdtw1.qa2.l1.voiplabs.net] Jan 10 20:55:22 www openser[21124]: DEBUG: to body ["18001033799" <sip:+18001033799@rdtw1.qa2.l1.voiplabs.net>]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:+14556660002@5934.rdtw1.qa2.l1.voiplabs.net>;tag=64.101.130.210^M To: "18001033799" <sip:+18001033799@rdtw1.qa2.l1.voiplabs.net>;tag=35^M Call-ID: 1-1140(a)64.101.130.210^M CSeq: 1 INVITE^M Max-Forwards: 70^M Content-Length: 145^M Contact: "18001033799" <sip:+118001033799@10.88.129.252: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:+18001033799@rdtw1.qa2.l1.voiplabs.net, o-uri=sip:+18001033799@10.88.128.77:5060, call_id=1-1140(a)64.101.130.210, from="14556660002" <sip:+14556660002@5934.rdtw1.qa2.l1.voiplabs.net>;tag=64.101.130.210, code=200, uid=n/a, fromtag=64.101.130.210, fromuri=sip:+14556660002@5934.rdtw1.qa2.l1.voiplabs.net, fromuri=sip:+14556660002@5934.rdtw1.qa2.l1.voiplabs.net, fromuser=+14556660002, fromdomain=5934.rdtw1.qa2.l1.voiplabs.net, to="18001033799" <sip:+18001033799@rdtw1.qa2.l1.voiplabs.net>;tag=35, totag=35, touri=sip:+18001033799@rdtw1.qa2.l1.voiplabs.net, 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:+18001033799@10.88.129.253>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:+18001033799@rdtw1.qa2.l1.voiplabs.net}Jan 10 20:55:22 www openser[21124]: DEBUG: get_hdr_field: <To> [64]; uri=[sip:+18001033799@rdtw1.qa2.l1.voiplabs.net] Jan 10 20:55:22 www openser[21124]: DEBUG: to body ["18001033799" <sip:+18001033799@rdtw1.qa2.l1.voiplabs.net>]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:+18001033799@10.88.129.253 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:+14556660002@5934.rdtw1.qa2.l1.voiplabs.net>;tag=64.101.130.210^M To: "18001033799" <sip:+18001033799@rdtw1.qa2.l1.voiplabs.net>;tag=35^M Call-ID: 1-1140(a)64.101.130.210^M Cseq: 2 ACK^M Contact: "14556660002" <sip:14556660002@64.101.130.210>^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:+118001033799@10.88.129.252: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 ^call_id=1-1140(a)64.101.130.210 ^cseq=1 ^contact="14556660002" <sip:+14556660002@64.101.130.210> ^from=sip:+14556660002@5934.rdtw1.qa2.l1.voiplabs.net ^fromtag=64.101.130.210 ^to=sip:+18001033799@rdtw1.qa2.l1.voiplabs.net ^totag=<null> ^method=INVITE ^ruri=sip:+18001033799@rdtw1.qa2.l1.voiplabs.net ^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 ^call_id=1-1140(a)64.101.130.210 ^cseq=1 ^contact="14556660002" <sip:+14556660002@64.101.130.210> ^from=sip:+14556660002@5934.rdtw1.qa2.l1.voiplabs.net ^fromtag=64.101.130.210 ^to=sip:+18001033799@rdtw1.qa2.l1.voiplabs.net ^totag=<null> ^method=INVITE ^ruri=sip:+18001033799@10.88.128.77: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:+18001033799@10.88.129.253>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:+18001033799@rdtw1.qa2.l1.voiplabs.net}Jan 10 20:55:22 www openser[21124]: DEBUG: get_hdr_field: <To> [64]; uri=[sip:+18001033799@rdtw1.qa2.l1.voiplabs.net] Jan 10 20:55:22 www openser[21124]: DEBUG: to body ["18001033799" <sip:+18001033799@rdtw1.qa2.l1.voiplabs.net>]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:+18001033799@10.88.129.253 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:+14556660002@5934.rdtw1.qa2.l1.voiplabs.net>;tag=64.101.130.210^M To: "18001033799" <sip:+18001033799@rdtw1.qa2.l1.voiplabs.net>;tag=35^M Call-ID: 1-1140(a)64.101.130.210^M Cseq: 2 ACK^M Contact: "14556660002" <sip:14556660002@64.101.130.210>^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:+118001033799@10.88.129.252: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: klaus.mailinglists(a)pernau.at&gt; To: sip(a)voiplabs.net&gt; CC: users(a)openser.org&gt; 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 > > Users(a)openser.org http://openser.org/cgi-bin/mailman/listinfo/users> > > -- > Klaus Darilion> nic.at>