[Kamailio-Users] Server Internal Error with sample config file : Kamailio 3.0 rc3

Wed Dec 23 14:50:23 CET 2009

Hello Henning.
I added debug but i did't find any errors.  

Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:611]: SIP
Request:
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:613]:
method:  <CANCEL>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:615]:
uri:     <sip:5501122334 at 10.0.0.211:5060>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:617]:
version: <SIP/2.0>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_via.c:1283]:
Found param type 232, <branch> =
<z9hG4bKc515f41b098abc8e1.77c62c857711f2aa1>; state=16
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_via.c:2296]: end
of header reached, state=5
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:499]:
parse_headers: Via found, flags=2
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:501]:
parse_headers: this is the first via
Dec 23 10:44:26 hostname : DEBUG: <core> [receive.c:137]: After
parse_msg...
Dec 23 10:44:26 hostname : DEBUG: <core> [receive.c:177]: preparing to
run routing scripts...
Dec 23 10:44:26 hostname : DEBUG: maxfwd [mf_funcs.c:85]: value = 70 
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_to.c:781]: end of
header reached, state=9
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:174]:
DEBUG: get_hdr_field: <To> [50]; uri=[sip:5501122334 at 10.0.0.211:5060] 
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:176]:
DEBUG: to body ["5501122334" <sip:5501122334 at 10.0.0.211:5060>  ]
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:154]:
get_hdr_field: cseq <CSeq>: <2315> <CANCEL>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:188]:
DEBUG: get_hdr_body : content_length=0
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:90]: found
end of header
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_to.c:174]: DEBUG:
add_param: tag=54158bb32e
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_to.c:781]: end of
header reached, state=29
Dec 23 10:44:26 hostname : DEBUG: sanity [mod_sanity.c:220]: all sanity
checks passed
Dec 23 10:44:26 hostname : DEBUG: siputils [checks.c:65]: no totag
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:764]: DEBUG:
t_lookupOriginalT: searching on hash entry 39181
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:470]: DEBUG: RFC3261
transaction matched, tid=c515f41b098abc8e1.77c62c857711f2aa1
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:861]: DEBUG:
t_lookupOriginalT: canceled transaction found (0xb6236810)! 
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:864]: DEBUG:
t_lookupOriginalT completed
Dec 23 10:44:26 hostname : DEBUG: tm [tm.c:937]: lookup_original:
t_lookupOriginalT returned: 0xb6236810
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:1387]: DEBUG:
t_newtran: msg id=8 , global msg id=7 , T on entrance=0xffffffff
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:528]: t_lookup_request:
start searching: hash=39181, isACK=0
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261
transaction matching failed
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:711]: DEBUG:
t_lookup_request: no transaction found
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:764]: DEBUG:
t_lookupOriginalT: searching on hash entry 39181
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:470]: DEBUG: RFC3261
transaction matched, tid=c515f41b098abc8e1.77c62c857711f2aa1
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:861]: DEBUG:
t_lookupOriginalT: canceled transaction found (0xb6236810)! 
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:864]: DEBUG:
t_lookupOriginalT completed
Dec 23 10:44:26 hostname : DEBUG: tm [t_cancel.c:308]: DEBUG:
cancel_branch: sending cancel...
Dec 23 10:44:26 hostname : DEBUG: tm [t_fwd.c:1094]: DEBUG: e2e_cancel:
e2e cancel proceeding
Dec 23 10:44:26 hostname : DEBUG: <core> [msg_translator.c:200]:
check_via_address(10.0.0.220, 10.0.0.220, 0)
Dec 23 10:44:26 hostname : DEBUG: tm [t_reply.c:1382]: DEBUG:
cleanup_uac_timers: RETR/FR timers reset
Dec 23 10:44:26 hostname : DEBUG: tm [t_reply.c:626]: DEBUG:
_reply_light: finished
Dec 23 10:44:26 hostname : DEBUG: tm [t_funcs.c:388]: SER: new
transaction fwd'ed
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [receive.c:280]: receive_msg:
cleaning up
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:621]: SIP
Reply  (status):
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:623]:
version: <SIP/2.0>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:625]:
status:  <200>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:627]:
reason:  <OK>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_via.c:1283]:
Found param type 232, <branch> = <z9hG4bKd099.40d7b237.0>; state=16
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_via.c:2296]: end
of header reached, state=5
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:499]:
parse_headers: Via found, flags=2
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:501]:
parse_headers: this is the first via
Dec 23 10:44:26 hostname : DEBUG: <core> [receive.c:137]: After
parse_msg...
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:1080]: DEBUG:
t_check_msg: msg id=10 global id=9 T start=0xffffffff
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_to.c:174]: DEBUG:
add_param: tag=969537555
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_to.c:781]: end of
header reached, state=29
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:174]:
DEBUG: get_hdr_field: <To> [64]; uri=[sip:5501122334 at 10.0.0.211:5060] 
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:176]:
DEBUG: to body ["5501122334" <sip:5501122334 at 10.0.0.211:5060>]
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:154]:
get_hdr_field: cseq <CSeq>: <2315> <CANCEL>
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:967]: DEBUG:
t_reply_matching: hash 39181 label 1932229892 branch 0
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:1018]: DEBUG:
t_reply_matching: reply matched (T=0xb6236810)!
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:1149]: DEBUG:
t_check_msg: msg id=10 global id=10 T end=0xb6236810
Dec 23 10:44:26 hostname : DEBUG: tm [t_reply.c:1900]: DEBUG:
reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
Dec 23 10:44:26 hostname : DEBUG: tm [t_reply.c:1913]: DEBUG: reply to
local CANCEL processed
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [receive.c:280]: receive_msg:
cleaning up
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:621]: SIP
Reply  (status):
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:623]:
version: <SIP/2.0>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:625]:
status:  <487>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:627]:
reason:  <Request Terminated>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_via.c:1283]:
Found param type 232, <branch> = <z9hG4bKd099.40d7b237.0>; state=16
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_via.c:2296]: end
of header reached, state=5
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:499]:
parse_headers: Via found, flags=2
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:501]:
parse_headers: this is the first via
Dec 23 10:44:26 hostname : DEBUG: <core> [receive.c:137]: After
parse_msg...
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:1080]: DEBUG:
t_check_msg: msg id=9 global id=8 T start=0xffffffff
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_via.c:1283]:
Found param type 232, <branch> =
<z9hG4bKc515f41b098abc8e1.77c62c857711f2aa1>; state=16
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_via.c:2296]: end
of header reached, state=5
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:499]:
parse_headers: Via found, flags=22
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:512]:
parse_headers: this is the second via
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_to.c:174]: DEBUG:
add_param: tag=969537555
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_to.c:781]: end of
header reached, state=29
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:174]:
DEBUG: get_hdr_field: <To> [64]; uri=[sip:5501122334 at 10.0.0.211:5060] 
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:176]:
DEBUG: to body ["5501122334" <sip:5501122334 at 10.0.0.211:5060>]
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:154]:
get_hdr_field: cseq <CSeq>: <2315> <INVITE>
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:967]: DEBUG:
t_reply_matching: hash 39181 label 1932229892 branch 0
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:1018]: DEBUG:
t_reply_matching: reply matched (T=0xb6236810)!
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:1149]: DEBUG:
t_check_msg: msg id=9 global id=9 T end=0xb6236810
Dec 23 10:44:26 hostname : DEBUG: tm [t_reply.c:1900]: DEBUG:
reply_received: org. status uas=180, uac[0]=180 local=0 is_invite=1)
Dec 23 10:44:26 hostname : DEBUG: <script>: incoming reply
Dec 23 10:44:26 hostname : DEBUG: tm [t_reply.c:1051]: ->>>>>>>>>
T_code=180, new_code=487
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:1080]: DEBUG:
t_check_msg: msg id=6 global id=6 T start=0xb6236810
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:1152]: DEBUG:
t_check_msg: T already found!
Dec 23 10:44:26 hostname : DEBUG: <core> [msg_translator.c:200]:
check_via_address(10.0.0.220, 10.0.0.220, 0)
Dec 23 10:44:26 hostname : DEBUG: tm [t_reply.c:1382]: DEBUG:
cleanup_uac_timers: RETR/FR timers reset
Dec 23 10:44:26 hostname : DEBUG: tm [t_reply.c:626]: DEBUG:
_reply_light: finished
Dec 23 10:44:26 hostname : DEBUG: tm [t_reply.c:1534]: DEBUG:
relay_reply: branch=0, save=0, relay=-1
Dec 23 10:44:26 hostname : DEBUG: tm [t_reply.c:1382]: DEBUG:
cleanup_uac_timers: RETR/FR timers reset
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [receive.c:280]: receive_msg:
cleaning up
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:611]: SIP
Request:
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:613]:
method:  <ACK>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:615]:
uri:     <sip:5501122334 at 10.0.0.211:5060>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:617]:
version: <SIP/2.0>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_via.c:1283]:
Found param type 232, <branch> =
<z9hG4bKc515f41b098abc8e1.77c62c857711f2aa1>; state=16
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_via.c:2296]: end
of header reached, state=5
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:499]:
parse_headers: Via found, flags=2
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:501]:
parse_headers: this is the first via
Dec 23 10:44:26 hostname : DEBUG: <core> [receive.c:137]: After
parse_msg...
Dec 23 10:44:26 hostname : DEBUG: <core> [receive.c:177]: preparing to
run routing scripts...
Dec 23 10:44:26 hostname : DEBUG: sl [sl_funcs.c:335]: to late to be a
local ACK!
Dec 23 10:44:26 hostname : DEBUG: maxfwd [mf_funcs.c:85]: value = 70 
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_to.c:174]: DEBUG:
add_param: tag=a6a1c5f60faecf035a1ae5b6e96e979a-bf11
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_to.c:781]: end of
header reached, state=29
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:174]:
DEBUG: get_hdr_field: <To> [92]; uri=[sip:5501122334 at 10.0.0.211:5060] 
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:176]:
DEBUG: to body ["5501122334" <sip:5501122334 at 10.0.0.211:5060>]
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:154]:
get_hdr_field: cseq <CSeq>: <2315> <ACK>
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:188]:
DEBUG: get_hdr_body : content_length=0
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/msg_parser.c:90]: found
end of header
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_to.c:174]: DEBUG:
add_param: tag=54158bb32e
Dec 23 10:44:26 hostname : DEBUG: <core> [parser/parse_to.c:781]: end of
header reached, state=29
Dec 23 10:44:26 hostname : DEBUG: sanity [mod_sanity.c:220]: all sanity
checks passed
Dec 23 10:44:26 hostname : DEBUG: siputils [checks.c:68]: totag found
Dec 23 10:44:26 hostname : DEBUG: rr [loose.c:108]: No Route headers
found
Dec 23 10:44:26 hostname : DEBUG: rr [loose.c:907]: There is no Route HF
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:1080]: DEBUG:
t_check_msg: msg id=11 global id=10 T start=0xffffffff
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:528]: t_lookup_request:
start searching: hash=39181, isACK=1
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:470]: DEBUG: RFC3261
transaction matched, tid=c515f41b098abc8e1.77c62c857711f2aa1
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:728]: DEBUG:
t_lookup_request: transaction found (T=0xb6236810)
Dec 23 10:44:26 hostname : DEBUG: tm [t_lookup.c:1149]: DEBUG:
t_check_msg: msg id=11 global id=11 T end=0xb6236810
Dec 23 10:44:26 hostname : DEBUG: tm [t_reply.c:1382]: DEBUG:
cleanup_uac_timers: RETR/FR timers reset
Dec 23 10:44:26 hostname : DEBUG: <core> [timer.c:593]: timer_add called
on an active timer 0xb6236858 (0xb6110a9c, 0xb6110a9c), flags 201
Dec 23 10:44:26 hostname : DEBUG: tm [t_funcs.c:184]: tm: put_on_wait:
transaction 0xb6236810 already on wait
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [usr_avp.c:629]:
DEBUG:destroy_avp_list: destroying list (nil)
Dec 23 10:44:26 hostname : DEBUG: <core> [receive.c:280]: receive_msg:
cleaning up

Ricardo.-

-----Mensaje original-----
De: Henning Westerholt [mailto:henning.westerholt at 1und1.de] 
Enviado el: martes, 22 de diciembre de 2009 19:41
Para: Ricardo Martinez
CC: users at lists.kamailio.org
Asunto: Re: [Kamailio-Users] Server Internal Error with sample config
file : Kamailio 3.0 rc3

On Tue, December 22, 2009 9:37 pm, Ricardo Martinez wrote:
> I'm using the sample configuration that comes with Kamailio RC3.
> (version: kamailio 3.0.0-rc3 (i386/linux)).
>
> I have two IP phones registered in the proxy.  If I call from one to
> another and the call is cancelled a "500 Server Internal Error"
message
> is send back to the caller (please see the debug attached) by the
proxy.
>
> This is not happening with Kamailio 1.4 or Opensips 1.6 (using the
> sample configurations).
>
> Could be some problem?

Hello Ricardo,

the error you face happens in the new tm module, which is different than
the one used in kamailio. Do you get perhaps an error in the kamailio
logging file?

> SIP/2.0 500 I'm terribly sorry, server error occurred (1/TM).

This means that a default error occurred in the processing, and a return
value of -1 was returned from the respective TM operation.

Regards,

Henning