On 22.03.2012 15:56, Daniel-Constantin Mierla wrote: 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

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.

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 >

Can you try with patches: http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=cf9269d… http://git.sip-router.org/cgi-bin/gitweb.cgi/sip-router/?a=commit;h=e4972eb… 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: