Hello list.
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?
10.0.0.220 - Caller
10.0.0.211 - Proxy
10.0.0.152 - Callee
U 10.0.0.220:5060 -> 10.0.0.211:5060
INVITE sip:5501122334@10.0.0.211:5060 SIP/2.0.
Via: SIP/2.0/UDP 10.0.0.220:5060;branch=z9hG4bKf9043df6290194056.e3af2c48f0fba0802.
Max-Forwards: 70.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060.
Call-ID: c8e55b952ba85701.
CSeq: 13486 INVITE.
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO.
Allow-Events: talk, hold, conference, LocalModeStatus.
Contact: "5501234567" sip:5501234567@10.0.0.220:5060;transport=udp;+sip.instance="urn:uuid: 00000000-0000-1000-8000-00085D1B6C7A".
Supported: gruu, path, timer, 100rel, replaces.
User-Agent: Aastra 57i/2.5.2.1010.
Content-Type: application/sdp.
Content-Length: 285.
.
v=0.
o=MxSIP 0 0 IN IP4 10.0.0.220.
s=SIP Call.
c=IN IP4 10.0.0.220.
t=0 0.
m=audio 3000 RTP/AVP 18 0 8 101.
a=rtpmap:18 G729/8000.
a=rtpmap:0 PCMU/8000.
a=rtpmap:8 PCMA/8000.
a=rtpmap:101 telephone-event/8000.
a=silenceSupp:off - - - -.
a=fmtp:101 0-15.
a=ptime:30.
a=sendrecv.
U 10.0.0.211:5060 -> 10.0.0.220:5060
SIP/2.0 100 trying -- your call is important to us.
Via: SIP/2.0/UDP 10.0.0.220:5060;branch=z9hG4bKf9043df6290194056.e3af2c48f0fba0802.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060.
Call-ID: c8e55b952ba85701.
CSeq: 13486 INVITE.
Server: kamailio (3.0.0-rc3 (i386/linux)).
Content-Length: 0.
Warning: 392 10.0.0.211:5060 "Noisy feedback tells: pid=9830 req_src_ip=10.0.0.220 req_src_port=5060 in_uri=sip:5501122334@10.0.0.211:5060 out_uri=sip:5501122334@10.0.0.152:5062 via_cnt==1".
.
U 10.0.0.211:5060 -> 10.0.0.152:5062
INVITE sip:5501122334@10.0.0.152:5062 SIP/2.0.
Record-Route: sip:10.0.0.211;lr=on.
Via: SIP/2.0/UDP 10.0.0.211;branch=z9hG4bKfee8.a17fc93.0.
Via: SIP/2.0/UDP 10.0.0.220:5060;branch=z9hG4bKf9043df6290194056.e3af2c48f0fba0802.
Max-Forwards: 69.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060.
Call-ID: c8e55b952ba85701.
CSeq: 13486 INVITE.
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO.
Allow-Events: talk, hold, conference, LocalModeStatus.
Contact: "5501234567" sip:5501234567@10.0.0.220:5060;transport=udp;+sip.instance="urn:uuid: 00000000-0000-1000-8000-00085D1B6C7A".
Supported: gruu, path, timer, 100rel, replaces.
User-Agent: Aastra 57i/2.5.2.1010.
Content-Type: application/sdp.
Content-Length: 285.
.
v=0.
o=MxSIP 0 0 IN IP4 10.0.0.220.
s=SIP Call.
c=IN IP4 10.0.0.220.
t=0 0.
m=audio 3000 RTP/AVP 18 0 8 101.
a=rtpmap:18 G729/8000.
a=rtpmap:0 PCMU/8000.
a=rtpmap:8 PCMA/8000.
a=rtpmap:101 telephone-event/8000.
a=silenceSupp:off - - - -.
a=fmtp:101 0-15.
a=ptime:30.
a=sendrecv.
U 10.0.0.152:5062 -> 10.0.0.211:5060
SIP/2.0 100 Trying.
Via: SIP/2.0/UDP 10.0.0.211;branch=z9hG4bKfee8.a17fc93.0.
Via: SIP/2.0/UDP 10.0.0.220:5060;branch=z9hG4bKf9043df6290194056.e3af2c48f0fba0802.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060.
Call-ID: c8e55b952ba85701.
CSeq: 13486 INVITE.
User-Agent: T20 9.41.0.70.
Content-Length: 0.
.
U 10.0.0.152:5062 -> 10.0.0.211:5060
SIP/2.0 180 Ringing.
Via: SIP/2.0/UDP 10.0.0.211;branch=z9hG4bKfee8.a17fc93.0.
Via: SIP/2.0/UDP 10.0.0.220:5060;branch=z9hG4bKf9043df6290194056.e3af2c48f0fba0802.
Record-Route: sip:10.0.0.211;lr=on.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060;tag=1211757599.
Call-ID: c8e55b952ba85701.
CSeq: 13486 INVITE.
Contact: sip:5501122334@10.0.0.152:5062.
User-Agent: T20 9.41.0.70.
Allow-Events: talk,hold,conference,refer,check-sync.
Content-Length: 0.
.
U 10.0.0.211:5060 -> 10.0.0.220:5060
SIP/2.0 180 Ringing.
Via: SIP/2.0/UDP 10.0.0.220:5060;branch=z9hG4bKf9043df6290194056.e3af2c48f0fba0802.
Record-Route: sip:10.0.0.211;lr=on.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060;tag=1211757599.
Call-ID: c8e55b952ba85701.
CSeq: 13486 INVITE.
Contact: sip:5501122334@10.0.0.152:5062.
User-Agent: T20 9.41.0.70.
Allow-Events: talk,hold,conference,refer,check-sync.
Content-Length: 0.
.
U 10.0.0.220:5060 -> 10.0.0.211:5060
CANCEL sip:5501122334@10.0.0.211:5060 SIP/2.0.
Via: SIP/2.0/UDP 10.0.0.220:5060;branch=z9hG4bKf9043df6290194056.e3af2c48f0fba0802.
Max-Forwards: 70.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060.
Call-ID: c8e55b952ba85701.
CSeq: 13486 CANCEL.
Supported: gruu, path.
User-Agent: Aastra 57i/2.5.2.1010.
Content-Length: 0.
.
U 10.0.0.211:5060 -> 10.0.0.152:5062
CANCEL sip:5501122334@10.0.0.152:5062 SIP/2.0.
Via: SIP/2.0/UDP 10.0.0.211;branch=z9hG4bKfee8.a17fc93.0.
Max-Forwards: 69.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060.
Call-ID: c8e55b952ba85701.
CSeq: 13486 CANCEL.
Content-Length: 0.
.
U 10.0.0.211:5060 -> 10.0.0.220:5060
SIP/2.0 200 canceling.
Via: SIP/2.0/UDP 10.0.0.220:5060;branch=z9hG4bKf9043df6290194056.e3af2c48f0fba0802.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060;tag=a6a1c5f60faecf035a1ae5b6e96e979a-cd 47.
Call-ID: c8e55b952ba85701.
CSeq: 13486 CANCEL.
Server: kamailio (3.0.0-rc3 (i386/linux)).
Content-Length: 0.
Warning: 392 10.0.0.211:5060 "Noisy feedback tells: pid=9831 req_src_ip=10.0.0.220 req_src_port=5060 in_uri=sip:5501122334@10.0.0.211:5060 out_uri=sip:5501122334@10.0.0.211:5060 via_cnt==1".
.
U 10.0.0.152:5062 -> 10.0.0.211:5060
SIP/2.0 200 OK.
Via: SIP/2.0/UDP 10.0.0.211;branch=z9hG4bKfee8.a17fc93.0.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060;tag=1211757599.
Call-ID: c8e55b952ba85701.
CSeq: 13486 CANCEL.
User-Agent: T20 9.41.0.70.
Content-Length: 0.
.
U 10.0.0.152:5062 -> 10.0.0.211:5060
SIP/2.0 487 Request Terminated.
Via: SIP/2.0/UDP 10.0.0.211;branch=z9hG4bKfee8.a17fc93.0.
Via: SIP/2.0/UDP 10.0.0.220:5060;branch=z9hG4bKf9043df6290194056.e3af2c48f0fba0802.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060;tag=1211757599.
Call-ID: c8e55b952ba85701.
CSeq: 13486 INVITE.
User-Agent: T20 9.41.0.70.
Content-Length: 0.
.
U 10.0.0.211:5060 -> 10.0.0.152:5062
ACK sip:5501122334@10.0.0.152:5062 SIP/2.0.
Via: SIP/2.0/UDP 10.0.0.211;branch=z9hG4bKfee8.a17fc93.0.
Max-Forwards: 69.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060;tag=1211757599.
Call-ID: c8e55b952ba85701.
CSeq: 13486 ACK.
Content-Length: 0.
.
U 10.0.0.211:5060 -> 10.0.0.220:5060
SIP/2.0 500 I'm terribly sorry, server error occurred (1/TM).
Via: SIP/2.0/UDP 10.0.0.220:5060;branch=z9hG4bKf9043df6290194056.e3af2c48f0fba0802.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060;tag=a6a1c5f60faecf035a1ae5b6e96e979a-cd 47.
Call-ID: c8e55b952ba85701.
CSeq: 13486 INVITE.
Server: kamailio (3.0.0-rc3 (i386/linux)).
Content-Length: 0.
Warning: 392 10.0.0.211:5060 "Noisy feedback tells: pid=9830 req_src_ip=10.0.0.220 req_src_port=5060 in_uri=sip:5501122334@10.0.0.211:5060 out_uri=sip:5501122334@10.0.0.152:5062 via_cnt==2".
.
U 10.0.0.220:5060 -> 10.0.0.211:5060
ACK sip:5501122334@10.0.0.211:5060 SIP/2.0.
Via: SIP/2.0/UDP 10.0.0.220:5060;branch=z9hG4bKf9043df6290194056.e3af2c48f0fba0802.
Max-Forwards: 70.
From: "5501234567" sip:5501234567@10.0.0.211:5060;tag=dbaa8e4386.
To: "5501122334" sip:5501122334@10.0.0.211:5060;tag=a6a1c5f60faecf035a1ae5b6e96e979a-cd 47.
Call-ID: c8e55b952ba85701.
CSeq: 13486 ACK.
User-Agent: Aastra 57i/2.5.2.1010.
Content-Length: 0.
.
Ricardo.-
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
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@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
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@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@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
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@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@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
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@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@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@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
Hi Ricardo,
ok, I completed the fix and tested. Fetch the git and let me know if works for you as well.
Thanks, Daniel
On 12/23/09 7:33 PM, Ricardo Martinez wrote:
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@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@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@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
Hello Daniel. Sorry to ask this question, but how can I make just an update from the git version?. I've tested the two commands in the kamailio web page without any luck. So I have to delete de kamailio directory and start the download again.
Thanks, Ricardo.-
-----Mensaje original----- De: Daniel-Constantin Mierla [mailto:miconda@gmail.com] Enviado el: miércoles, 23 de diciembre de 2009 18:41 Para: Ricardo Martinez CC: Henning Westerholt; users@lists.kamailio.org Asunto: Re: [Kamailio-Users] Server Internal Error with sample config file : Kamailio 3.0 rc3
Hi Ricardo,
ok, I completed the fix and tested. Fetch the git and let me know if works for you as well.
Thanks, Daniel
On 12/23/09 7:33 PM, Ricardo Martinez wrote:
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@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@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@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
Hello Ricardo,
I am doing:
git pull origin
Cheers, Daniel
On 12/24/09 1:43 PM, Ricardo Martinez wrote:
Hello Daniel. Sorry to ask this question, but how can I make just an update from the git version?. I've tested the two commands in the kamailio web page without any luck. So I have to delete de kamailio directory and start the download again.
Thanks, Ricardo.-
-----Mensaje original----- De: Daniel-Constantin Mierla [mailto:miconda@gmail.com] Enviado el: miércoles, 23 de diciembre de 2009 18:41 Para: Ricardo Martinez CC: Henning Westerholt; users@lists.kamailio.org Asunto: Re: [Kamailio-Users] Server Internal Error with sample config file : Kamailio 3.0 rc3
Hi Ricardo,
ok, I completed the fix and tested. Fetch the git and let me know if works for you as well.
Thanks, Daniel
On 12/23/09 7:33 PM, Ricardo Martinez wrote:
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@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@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@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
Hello Daniel.
Ok.. i just read this mail, I downloaded the whole package again. J
Anyway.. now is working as expected!... Thanks for your help!
Regards,
Ricardo.-
De: Daniel-Constantin Mierla [mailto:miconda@gmail.com] Enviado el: jueves, 24 de diciembre de 2009 10:37 Para: Ricardo Martinez CC: Henning Westerholt; users@lists.kamailio.org Asunto: Re: [Kamailio-Users] Server Internal Error with sample config file : Kamailio 3.0 rc3
Hello Ricardo,
I am doing:
git pull origin
Cheers, Daniel
On 12/24/09 1:43 PM, Ricardo Martinez wrote:
Hello Daniel. Sorry to ask this question, but how can I make just an update from the git version?. I've tested the two commands in the kamailio web page without any luck. So I have to delete de kamailio directory and start the download again.
Thanks, Ricardo.-
-----Mensaje original----- De: Daniel-Constantin Mierla [mailto:miconda@gmail.com] Enviado el: miércoles, 23 de diciembre de 2009 18:41 Para: Ricardo Martinez CC: Henning Westerholt; users@lists.kamailio.org Asunto: Re: [Kamailio-Users] Server Internal Error with sample config file : Kamailio 3.0 rc3
Hi Ricardo,
ok, I completed the fix and tested. Fetch the git and let me know if works for you as well.
Thanks, Daniel
On 12/23/09 7:33 PM, Ricardo Martinez wrote:
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@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 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 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 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 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 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 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@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@lists.kamailio.org http://lists.kamailio.org/cgi-bin/mailman/listinfo/users http://lists.openser-project.org/cgi-bin/mailman/listinfo/users
-
Daniel-Constantin Mierla -
Henning Westerholt -
Ricardo Martinez