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) failed
Jan 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) failed
Jan 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) failed
Jan 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=2
Jan 10 20:55:22 www openser[21124]: Found param type 232, <branch> = <z9hG4bK7d34.d8cbc746.0>; state=16
Jan 10 20:55:22 www openser[21124]: end of header reached, state=5
Jan 10 20:55:22 www openser[21124]: parse_headers: Via found, flags=2
Jan 10 20:55:22 www openser[21124]: parse_headers: this is the first via
Jan 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 it
Jan 10 20:55:22 www openser[21124]: DEBUG: t_check: msg id=19 global id=18 T start=0xffffffff
Jan 10 20:55:22 www openser[21124]: parse_headers: flags=22
Jan 10 20:55:22 www openser[21124]: Found param type 232, <branch> = <z9hG4bK175-64.101.130.210>; state=16
Jan 10 20:55:22 www openser[21124]: end of header reached, state=5
Jan 10 20:55:22 www openser[21124]: parse_headers: Via found, flags=22
Jan 10 20:55:22 www openser[21124]: parse_headers: this is the second via
Jan 10 20:55:22 www openser[21124]: DEBUG: add_param: tag=35
Jan 10 20:55:22 www openser[21124]: DEBUG:parse_to:end of header reached, state=29
Jan 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=8
Jan 10 20:55:22 www openser[21124]: DEBUG: t_reply_matching: hash 17367 label 1685896333 branch 0
Jan 10 20:55:22 www openser[21124]: DEBUG:tm:REF_UNSAFE: after is 1
Jan 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=8
Jan 10 20:55:22 www openser[21124]: DBG: trans=0x283fe3a8, callback type 2, id 0 entered
Jan 10 20:55:22 www openser[21124]: parse_headers: flags=8
Jan 10 20:55:22 www openser[21124]: DEBUG: t_check: msg id=19 global id=19 T end=0x283fe3a8
Jan 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=200
Jan 10 20:55:22 www openser[21124]: DEBUG:tm:relay_reply: branch=0, save=0, relay=0
Jan 10 20:55:22 www openser[21124]:  old size: 844, new size: 783
Jan 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@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]: 0x283fe3f0
Jan 10 20:55:22 www openser[21124]: DEBUG:tm:relay_reply: sent buf=0x81351c8: SIP/2.0 2..., shmem=0x283fe090: SIP/2.0 2
Jan 10 20:55:22 www openser[21124]: DBG: trans=0x283fe3a8, callback type 128, id 0 entered
Jan 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@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.net
Jan 10 20:55:22 www openser[21124]: DEBUG: cleanup_uac_timers: RETR/FR timers reset
Jan 10 20:55:22 www openser[21124]:  DEBUG:tm:UNREF_UNSAFE: after is 0
Jan 10 20:55:22 www openser[21124]: DEBUG:destroy_avp_list: destroying list 0x0
Jan 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=2
Jan 10 20:55:22 www openser[21124]: end of header reached, state=5
Jan 10 20:55:22 www openser[21124]: parse_headers: Via found, flags=2
Jan 10 20:55:22 www openser[21124]: parse_headers: this is the first via
Jan 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=100
Jan 10 20:55:22 www openser[21124]: DEBUG: add_param: tag=35
Jan 10 20:55:22 www openser[21124]: DEBUG:parse_to:end of header reached, state=29
Jan 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=200
Jan 10 20:55:22 www openser[21124]: is_preloaded: No
Jan 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 5060
Jan 10 20:55:22 www openser[21124]: check_self: host != me
Jan 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 5060
Jan 10 20:55:22 www openser[21124]: after_loose: Topmost route URI: 'sip:10.88.128.74;lr;ftag=64.101.130.210' is me
Jan 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 router
Jan 10 20:55:22 www openser[21124]: DEBUG: t_newtran: msg id=20 , global msg id=19 , T on entrance=0xffffffff
Jan 10 20:55:22 www openser[21124]: parse_headers: flags=ffffffffffffffff
Jan 10 20:55:22 www openser[21124]: DEBUG: get_hdr_body : content_length=0
Jan 10 20:55:22 www openser[21124]: found end of header
Jan 10 20:55:22 www openser[21124]: parse_headers: flags=78
Jan 10 20:55:22 www openser[21124]: t_lookup_request: start searching: hash=17364, isACK=1
Jan 10 20:55:22 www openser[21124]: DEBUG: proceeding to pre-RFC3261 transaction matching
Jan 10 20:55:22 www openser[21124]: DEBUG: t_lookup_request: no transaction found
Jan 10 20:55:22 www openser[21124]: DEBUG:tm:t_relay: forwarding ACK
Jan 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@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=1
Jan 10 20:55:22 www openser[21124]: DEBUG:destroy_avp_list: destroying list 0x0
Jan 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:5060
Jan 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@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=s
Jan 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@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.net
Jan 10 20:55:22 www openser[21346]: DEBUG: t_newtran: msg id=8 , global msg id=7 , T on entrance=0xffffffff
Jan 10 20:55:22 www openser[21346]: parse_headers: flags=ffffffffffffffff
Jan 10 20:55:22 www openser[21346]: parse_headers: flags=78
Jan 10 20:55:22 www openser[21346]: t_lookup_request: start searching: hash=17367, isACK=0
Jan 10 20:55:22 www openser[21346]: DEBUG: RFC3261 transaction matched, tid=175-64.101.130.210
Jan 10 20:55:22 www openser[21346]: DEBUG:tm:REF_UNSAFE: after is 1
Jan 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 0
Jan 10 20:55:22 www openser[21346]: DEBUG:destroy_avp_list: destroying list 0x0
Jan 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=2
Jan 10 20:55:22 www openser[21124]: end of header reached, state=5
Jan 10 20:55:22 www openser[21124]: parse_headers: Via found, flags=2
Jan 10 20:55:22 www openser[21124]: parse_headers: this is the first via
Jan 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=100
Jan 10 20:55:22 www openser[21124]: DEBUG: add_param: tag=35
Jan 10 20:55:22 www openser[21124]: DEBUG:parse_to:end of header reached, state=29
Jan 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=200
Jan 10 20:55:22 www openser[21124]: is_preloaded: No
Jan 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 5060
Jan 10 20:55:22 www openser[21124]: check_self: host != me
Jan 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 5060
Jan 10 20:55:22 www openser[21124]: after_loose: Topmost route URI: 'sip:10.88.128.74;lr;ftag=64.101.130.210' is me
Jan 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 router
Jan 10 20:55:22 www openser[21124]: DEBUG: t_newtran: msg id=21 , global msg id=20 , T on entrance=0xffffffff
Jan 10 20:55:22 www openser[21124]: parse_headers: flags=ffffffffffffffff
Jan 10 20:55:22 www openser[21124]: DEBUG: get_hdr_body : content_length=0
Jan 10 20:55:22 www openser[21124]: found end of header
Jan 10 20:55:22 www openser[21124]: parse_headers: flags=78
Jan 10 20:55:22 www openser[21124]: t_lookup_request: start searching: hash=17364, isACK=1
Jan 10 20:55:22 www openser[21124]: DEBUG: proceeding to pre-RFC3261 transaction matching
Jan 10 20:55:22 www openser[21124]: DEBUG: t_lookup_request: no transaction found
Jan 10 20:55:22 www openser[21124]: DEBUG:tm:t_relay: forwarding ACK
Jan 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@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=1
Jan 10 20:55:22 www openser[21124]: DEBUG:destroy_avp_list: destroying list 0x0
Jan 10 20:55:22 www openser[21124]: receive_msg: cleaning up
Jan 10 20:55:23 www openser[21376]: DEBUG: timer routine:1,tl=0x283fe4d4 next=0x0
Jan 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@pernau.at
> To: sip@voiplabs.net
> CC: users@openser.org
> 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@openser.org http://openser.org/cgi-bin/mailman/listinfo/users
>
>
> --
> Klaus Darilion
> nic.at
>