[SR-Users] is $td.did avp a normal avp?

Daniel-Constantin Mierla miconda at gmail.com
Tue Apr 26 14:48:31 CEST 2011 

Hi Juha,

On 4/26/11 12:58 PM, Juha Heinanen wrote:
> Daniel-Constantin Mierla writes:
>
>> afaik, the list should be saved for tm lifetime. If you run with high
>> debug level, do you see any message when the list is destroyed?
> daniel,
>
> plenty, but they don't tell me anything.  what does this mean?
>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG:<core>  [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
this tells that the avp list was null. The message is printed 6 times 
since ser added 5 more avp lists - kamailio used to have 1, the first, 
corresponding to FROM_URI list in ser notation. So, it looks like all 
the avps list were null when the core cleaned the received message. If 
there was an avp in any of the lists and it was not deleted, then the 
lists are null because they were moved to transaction.

Could it be that this avp is deleted automatically somewhere in a module?

Cheers,
Daniel

>
> below is what comes to syslog when request is forwarded in route block
> and when reply is received.
>
> i have called t_newtrans() before i call t_relay() if that could explain
> anything.
>
> -- juha
>
> when request if forwarded:
>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: INFO: Routing INVITE to contacts<sip:test at 192.98.102.10:5074;transport=udp>  and<<null>>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG: tm [t_lookup.c:1379]: DEBUG: t_newtran: msg id=28 , global msg id=28 , T on entrance=0xb49932e8
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG: tm [t_lookup.c:1384]: DEBUG: t_newtran: transaction already in process 0xb49932e8
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG:<core>  [select.c:424]: Calling SELECT 0xb73e5dd0
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG: permissions [address.c:395]: looking for<2, a6662c0, 5074>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG:<core>  [dns_cache.c:3392]: dns_sip_resolve(192.98.102.10, 0, 0), ip, ret=0
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG:<core>  [msg_translator.c:204]: check_via_address(192.98.102.10, 192.98.102.10, 0)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG: tm [t_funcs.c:388]: SER: new transaction fwd'ed
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG:<core>  [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG:<core>  [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG:<core>  [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG:<core>  [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG:<core>  [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG:<core>  [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19855]: DEBUG:<core>  [xavp.c:423]: destroying xavp list (nil)
>
> when 180 reply is received:
>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/msg_parser.c:640]: SIP Reply  (status):
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG:<core>  [receive.c:146]: After parse_msg...
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/msg_parser.c:642]:  version:<SIP/2.0>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=29 global id=28 T start=0xffffffff
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/msg_parser.c:644]:  status:<180>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG:<core>  [parser/parse_to.c:803]: end of header reached, state=10
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/msg_parser.c:646]:  reason:<Ringing>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG:<core>  [parser/msg_parser.c:187]: DEBUG: get_hdr_field:<To>  [20]; uri=[sip:test at test.fi]
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/parse_via.c:1287]: Found param type 232,<branch>  =<z9hG4bK358f.316a3396f38bbae0398336dc8ee68999.0>; state=9
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG:<core>  [parser/msg_parser.c:189]: DEBUG: to body [<sip:test at test.fi>#015#012]
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/parse_via.c:2343]: parse_via: next_via
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG:<core>  [parser/msg_parser.c:167]: get_hdr_field: cseq<CSeq>:<794>  <INVITE>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/parse_via.c:1287]: Found param type 235,<rport>  =<5074>; state=6
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [t_lookup.c:967]: DEBUG: t_reply_matching: hash 63571 label 0 branch 0
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/parse_via.c:1287]: Found param type 232,<branch>  =<z9hG4bKypzwzcfe>; state=16
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [t_lookup.c:1018]: DEBUG: t_reply_matching: reply matched (T=0xb49932e8)!
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/parse_via.c:2300]: end of header reached, state=5
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/msg_parser.c:515]: parse_headers: Via found, flags=2
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [t_hooks.c:288]: DBG: trans=0xb49932e8, callback type 2, id 0 entered
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/msg_parser.c:517]: parse_headers: this is the first via
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [t_lookup.c:1150]: DEBUG: t_check_msg: msg id=29 global id=29 T end=0xb49932e8
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [receive.c:146]: After parse_msg...
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=35 global id=34 T start=0xffffffff
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/parse_to.c:174]: DEBUG: add_param: tag=llpls
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [t_reply.c:2017]: DEBUG: reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=1)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/parse_to.c:803]: end of header reached, state=29
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=29 global id=29 T start=0xb49932e8
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/msg_parser.c:187]: DEBUG: get_hdr_field:<To>  [30]; uri=[sip:test at test.fi]
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/msg_parser.c:189]: DEBUG: to body [<sip:test at test.fi>]
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [t_lookup.c:1153]: DEBUG: t_check_msg: T already found!
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG:<core>  [parser/msg_parser.c:167]: get_hdr_field: cseq<CSeq>:<794>  <INVITE>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [tm.c:968]: DEBUG:t_check_status: checked status is<100>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [t_lookup.c:967]: DEBUG: t_reply_matching: hash 63571 label 0 branch 0
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [t_lookup.c:1018]: DEBUG: t_reply_matching: reply matched (T=0xb49932e8)!
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=29 global id=29 T start=0xb49932e8
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [t_hooks.c:288]: DBG: trans=0xb49932e8, callback type 2, id 0 entered
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [t_lookup.c:1153]: DEBUG: t_check_msg: T already found!
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [t_lookup.c:1150]: DEBUG: t_check_msg: msg id=35 global id=35 T end=0xb49932e8
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [tm.c:968]: DEBUG:t_check_status: checked status is<100>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [t_reply.c:2017]: DEBUG: reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=1)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [t_reply.c:1132]: ->>>>>>>>>  T_code=0, new_code=100
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG: tm [t_reply.c:1634]: DEBUG: relay_reply: branch=0, save=0, relay=-1
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG:<core>  [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=35 global id=35 T start=0xb49932e8
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [t_lookup.c:1153]: DEBUG: t_check_msg: T already found!
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG:<core>  [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [tm.c:968]: DEBUG:t_check_status: checked status is<180>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG:<core>  [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=35 global id=35 T start=0xb49932e8
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG:<core>  [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [t_lookup.c:1153]: DEBUG: t_check_msg: T already found!
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [tm.c:968]: DEBUG:t_check_status: checked status is<180>
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG:<core>  [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [t_lookup.c:1081]: DEBUG: t_check_msg: msg id=35 global id=35 T start=0xb49932e8
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG:<core>  [usr_avp.c:646]: DEBUG:destroy_avp_list: destroying list (nil)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [t_lookup.c:1153]: DEBUG: t_check_msg: T already found!
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19853]: DEBUG:<core>  [xavp.c:423]: destroying xavp list (nil)
> Apr 26 13:31:43 sip /usr/sbin/sip-proxy[19854]: DEBUG: tm [tm.c:968]: DEBUG:t_check_status: checked status is<180>
>
> _______________________________________________
> SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
> sr-users at lists.sip-router.org
> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users

-- 
Daniel-Constantin Mierla
http://www.asipto.com

More information about the sr-users mailing list