Hello Daniel.
Thanks for the help. I just downloaded the last GIT version, I even take a look at the
added lines in the t_reply.c file, unfortunately the behavior is still the same.
Any Ideas?
Ricardo.-
-----Mensaje original-----
De: Daniel-Constantin Mierla [mailto:miconda@gmail.com]
Enviado el: miƩrcoles, 23 de diciembre de 2009 13:39
Para: Ricardo Martinez
CC: Henning Westerholt; users(a)lists.kamailio.org
Asunto: Re: [Kamailio-Users] Server Internal Error with sample config file : Kamailio 3.0
rc3
Hello,
get the last GIT version of kamailio_3.0 and try again. Hopefully is
fixed, thanks to Andrei's help - the issue was using a failure_route
which adds no new branch and Kamailio's behavior of dropping replies for
previous branches. Let me know if all goes ok now.
Thanks,
Daniel
On 12/23/09 2:50 PM, Ricardo Martinez wrote:
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@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@10.0.0.211:5060]
Dec 23 10:44:26 hostname : DEBUG:<core> [parser/msg_parser.c:176]:
DEBUG: to body ["5501122334"<sip:5501122334@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@10.0.0.211:5060]
Dec 23 10:44:26 hostname : DEBUG:<core> [parser/msg_parser.c:176]:
DEBUG: to body ["5501122334"<sip:5501122334@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@10.0.0.211:5060]
Dec 23 10:44:26 hostname : DEBUG:<core> [parser/msg_parser.c:176]:
DEBUG: to body ["5501122334"<sip:5501122334@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@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@10.0.0.211:5060]
Dec 23 10:44:26 hostname : DEBUG:<core> [parser/msg_parser.c:176]:
DEBUG: to body ["5501122334"<sip:5501122334@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@1und1.de]
Enviado el: martes, 22 de diciembre de 2009 19:41
Para: Ricardo Martinez
CC: users(a)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
_______________________________________________
Kamailio (OpenSER) - Users mailing list
Users(a)lists.kamailio.org
http://lists.kamailio.org/cgi-bin/mailman/listinfo/users
http://lists.openser-project.org/cgi-bin/mailman/listinfo/users