[Users] 1.2.0 and retransmissions

Bogdan-Andrei Iancu bogdan at voice-system.ro
Mon Feb 19 10:22:43 CET 2007 

Hi Helge,

may the fix I did Friday solved the problem - it was a function 
parameter which was not updated and truncating  happened after ~1.1 hour 
of  running (it was an "int" instead of "long long" )....

regards,
bogdan

Helge Waastad wrote:
> 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