[Users] 1.2.0 and retransmissions

Helge Waastad helge at smartnet.no
Sat Feb 17 09:59:28 CET 2007 

Hi,
this is weird.

Since I cvs'ed yesterday, I have'nt been able to recreate the rtx
situation.

I will still try to regenerate the fault, but earlier I could just
REGISTER, Un-REGISTER a few times and the rtx started.

I'll get back to you, asap.

br hw


On fre, 2007-02-16 at 20:00 +0200, Bogdan-Andrei Iancu wrote:
> Hi Helge,
> 
> thanks for the log - what is very strange is the timeout values - 
> identical for all retransmission; I applied on CVS more debug logs and 
> also made a small fix in timers (small, but relevant ;) ). Could you 
> please update and give it another try ? again, log are most helpful...
> 
> thanks and regards,
> bogdan
> 
> Helge Waastad wrote:
> > Hi Bogdan,
> > this is what I see:
> >
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > Dispatcher-02: [LB]:5060 <= 10.46.11.104:5060 REGISTER from:
> > sip:[id]@[domain]
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > parse_headers: flags=200 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]: found end
> > of header 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > find_first_route: No Route headers found 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > loose_route: There is no Route HF 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > Dispatcher-02: Request from UAC...
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > parse_headers: flags=80 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > Dispatcher-02: UAC behind NAT...
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > parse_headers: flags=800 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > DISPATCHER:ds_select_dst: set index [1->0] 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > DISPATCHER:ds_select_dst: alg hash [4169264799] 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > DISPATCHER:ds_select_dst: selected [0-1/0/0] <sip:[SP]:5080> 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > Dispatcher-02: [LB]:5060 => sip:[SP]:5080 REGISTER
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > parse_headers: flags=ffffffffffffffff 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]: DEBUG:
> > t_newtran: msg id=1018 , global msg id=1017 , T on entrance=0xffffffff 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > parse_headers: flags=ffffffffffffffff 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > parse_headers: flags=78 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > t_lookup_request: start searching: hash=51317, isACK=0 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]: DEBUG:
> > RFC3261 transaction matching failed 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]: DEBUG:
> > t_lookup_request: no transaction found 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]: DBG:
> > trans=0xb60d8368, callback type 1, id 0 entered 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]: DEBUG:
> > mk_proxy: doing DNS lookup... 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > check_via_address(10.46.11.104, 10.46.11.104, 0) 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]: DEBUG:
> > add_to_tail_of_timer[4]: 0xb60d84b4 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > DEBUG:tm:_set_fr_retr: FR_TIMER = 3 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]: DEBUG:
> > add_to_tail_of_timer[0]: 0xb60d84d0 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > DEBUG:tm:t_relay_to: new transaction fwd'ed 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > DEBUG:tm:UNREF_UNSAFE: after is 0 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > DEBUG:destroy_avp_list: destroying list (nil) 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28921]:
> > receive_msg: cleaning up 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > timer routine:4,tl=0xb60d84b4 next=(nil), timeout=785159744 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > retransmission_handler : request resending (t=0xb60d8368,
> > REGISTER  ... ) 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > add_to_tail_of_timer[5]: 0xb60d84b4 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > retransmission_handler : done 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > timer routine:5,tl=0xb60d84b4 next=(nil), timeout=785759744 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > retransmission_handler : request resending (t=0xb60d8368,
> > REGISTER  ... ) 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > add_to_tail_of_timer[6]: 0xb60d84b4 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > retransmission_handler : done 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > timer routine:6,tl=0xb60d84b4 next=(nil), timeout=786759744 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > retransmission_handler : request resending (t=0xb60d8368,
> > REGISTER  ... ) 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > add_to_tail_of_timer[7]: 0xb60d84b4 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > retransmission_handler : done 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > timer routine:7,tl=0xb60da30c next=0xb60de19c, timeout=788659744 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > timer routine:7,tl=0xb60de19c next=0xb60d84b4, timeout=788659744 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > timer routine:7,tl=0xb60d84b4 next=(nil), timeout=788759744 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > retransmission_handler : request resending (t=0xb60d8368,
> > REGISTER  ... ) 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > add_to_tail_of_timer[7]: 0xb60d84b4 
> > Feb 16 08:22:31 proxy-02 /usr/sbin/openser-dispatcher[28926]: DEBUG:
> > retransmission_handler : done
> >
> > br hw
> >
> >
> >
> > On tor, 2007-02-15 at 19:05 +0200, Bogdan-Andrei Iancu wrote: 
> >   
> >> debug 9 :) ...of the whole transaction...
> >>
> >> thanks,
> >> bogdan
> >>
> >> Helge Waastad wrote:
> >>     
> >>> Hi,
> >>> no there are no retransmissions from the UAC.
> >>>
> >>> What level do you want the debug on?
> >>>
> >>> br hw
> >>>
> >>>
> >>>
> >>> On tor, 2007-02-15 at 18:29 +0200, Bogdan-Andrei Iancu wrote:
> >>>   
> >>>       
> >>>> Hi Helge,
> >>>>
> >>>> is it a way to reproduce this? is there any retransmission from UAC to 
> >>>> LB? do you have a debug log for this?
> >>>>
> >>>> regards,
> >>>> bogdan
> >>>>
> >>>> Helge Waastad wrote:
> >>>>     
> >>>>         
> >>>>> Hi,
> >>>>> I've started to notice a lot of retransmissions in my 1.2.0 test lab.
> >>>>>
> >>>>> I'm running two LB(dispatcher) and two SP's on two servers, using
> >>>>> separate ports.
> >>>>>
> >>>>> What I se is this:
> >>>>>
> >>>>> SP:5080         LB:5060           UAC:5060
> >>>>> |                 |                | <Call><PFrame><Time>
> >>>>> |                 |                |
> >>>>> |                 |<-- REGISTER F1<|  1 PF:1   08:09:21.1442
> >>>>> |                 |                |
> >>>>> |<--- REGISTER F2<|                |  1 PF:2   08:09:21.1446
> >>>>> |                 |                |
> >>>>> |<--- REGISTER F3<|                |  1 PF:3   08:09:21.1469
> >>>>> |                 |                |
> >>>>> |<--- REGISTER F4<|                |  1 PF:4   08:09:21.1469
> >>>>> |                 |                |
> >>>>> |<--- REGISTER F5<|                |  1 PF:5   08:09:21.1469
> >>>>> |                 |                |
> >>>>> |<--- REGISTER F6<|                |  1 PF:6   08:09:21.1470
> >>>>> |                 |                |
> >>>>> |>F7 100 Trying ->|                |  1 PF:7   08:09:21.1615
> >>>>> |                 |                |
> >>>>> |>F8 100 Trying ->|                |  1 PF:8   08:09:21.1673
> >>>>> |                 |                |
> >>>>> |>F9 100 Trying ->|                |  1 PF:9   08:09:21.1714
> >>>>>
> >>>>>
> >>>>> dns_failover and blacklists are disabled
> >>>>>
> >>>>> Using the same tm timer configurations that I've been using on 1.1.1
> >>>>> (basically default values)
> >>>>>
> >>>>> Can anyone tell me what triggers retransmission here?
> >>>>>
> >>>>> (after register, the UAC sends SUBSCRIBE and the same rtx happens)
> >>>>>
> >>>>> br hw
> >>>>>
> >>>>>
> >>>>> _______________________________________________
> >>>>> Users mailing list
> >>>>> Users at openser.org
> >>>>> http://openser.org/cgi-bin/mailman/listinfo/users
> >>>>>
> >>>>>   
> >>>>>       
> >>>>>           
> >>>   
> >>>       
> >
> >   
>

More information about the Users mailing list