The problem was on caching key, which used to be msg->id, but it is not
enough, because same message can be processed by a different process
(timeout/failure_route, async, ...).
Some of the time related PVs were using pid in the key for caching the
value, but not $TV(...). I added some helper functions in core and
updated the pv module to use them for all time PVs.
If it is working, you can backport or let me know the results and I can
backport.
Thanks,
Daniel
On 3/23/12 11:16 AM, Daniel-Constantin Mierla wrote:
On 3/23/12 11:12 AM, Klaus Darilion wrote:
Almost no traffic. Only my test-client. Thus, for
all the received
messages you see the timestamps in the log I attached to last email.
ok, I will
push a patch soon -- it is an issue that is there for some
time, unlikely to happen on production, but more probable on
light-weight testing environments.
Cheers,
Daniel
regards
Klaus
On 23.03.2012 10:32, Daniel-Constantin Mierla wrote:
> One more question, do you have lot of traffic there, or is testing with
> few clients?
>
> Cheers,
> Daniel
>
> On 3/23/12 8:58 AM, Klaus Darilion wrote:
>>
>>
>> On 22.03.2012 15:56, Daniel-Constantin Mierla wrote:
>>> Hello,
>>>
>>> On 3/22/12 11:08 AM, Klaus Darilion wrote:
>>>> Hi!
>>>>
>>>> Is this by design? I would expect it to be either the same value
>>>> as in
>>>> the request route, or even better to be calculated new every time it
>>>> enters the failure route.
>>> $TV(...) takes inner name, any of them is 0? Btw, is it 0 or $null?
>>
>> Sorry for the missing information. I discovered the problem when using
>> the cached versions: (s) and (u).
>>
>> The problem seems to happen not all the time, maybe related to
>> processes which processed the messages. I couldn't find a
>> problem-pattern.
>>
>> version: kamailio 3.3.0-dev5 (i386/linux) 7a8ad6-dirty
>> flags: STATS: Off, USE_IPV6, USE_TCP, USE_TLS, TLS_HOOKS,
>> USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM,
>> SHM_MMAP, PKG_MALLOC, DBG_QM_MALLOC, USE_FUTEX,
>> FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR,
>> USE_DST_BLACKLIST, HAVE_RESOLV_RES
>> ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16,
>> MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 4MB
>> poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
>> id: 7a8ad6 -dirty
>>
>> # Message is received and forwarded
>> [28766] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488956.78208
>> #No answer yet, retransmission is received
>> [28767] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488956.578226
>> #No answer yet, second retransmission is received
>> [28768] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488957.578266
>> #After 3 seconds the failure route triggers
>> $TV(s).$TV(u) = 0.0
>> [28770] $TV(s) == $null
>> [28770] $TV(u) == $null
>>
>> Bug: (s) and (u) are $null.
>>
>> [28767] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488966.235403
>> [28768] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488966.735379
>> [28769] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488967.735787
>> [28770] FAILURE_ROUTE: $TV(s).$TV(u) = 1332488969.214139
>> [28770] $TV(s) == 1332488969
>> [28770] $TV(u) == 214139
>>
>> May be correct
>>
>> [28768] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488977.141683
>> [28769] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488977.640992
>> [28766] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488978.641067
>> [28770] FAILURE_ROUTE: $TV(s).$TV(u) = 1332488980.89135
>> [28770] $TV(s) == 1332488980
>> [28770] $TV(u) == 89135
>>
>> May be correct
>>
>> [28768] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488983.199731
>> [28769] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488983.699332
>> [28766] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488984.699386
>> [28770] FAILURE_ROUTE: $TV(s).$TV(u) = 1332488986.151654
>> [28770] $TV(s) == 1332488986
>> [28770] $TV(u) == 151654
>>
>> May be correct
>>
>> [28769] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488989.158925
>> [28766] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488989.658643
>> [28767] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488990.658706
>> [28770] FAILURE_ROUTE: $TV(s).$TV(u) = 1332488986.151654
>> [28770] $TV(s) == 1332488986
>> [28770] $TV(u) == 151654
>>
>> Bug: $TV is the same value as in the last failure route of the last
>> message
>>
>> [28769] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488995.70218
>> [28766] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488995.570014
>> [28767] REQUEST_ROUTE: $TV(s).$TV(u) = 1332488996.570029
>> [28770] FAILURE_ROUTE: $TV(s).$TV(u) = 1332488998.26641
>> [28770] $TV(s) == 1332488998
>> [28770] $TV(u) == 26641
>>
>> May be correct
>>
>>
>> regards
>> Klaus
>
--
Daniel-Constantin Mierla
Kamailio Advanced Training, April 23-26, 2012, Berlin, Germany