Hello,
it seems like that Cisco 827-V router doesn't include any from-tag within its INVITEs...which is NOT RFC CONFORM!. It may be due to some kind of proprietary function mode. There is nothing we can do on the SEMS side to solve the problem.
Does anybody else have such a gateway and got it work with voicemail?
-Raphael.
----- Original Message ----- From: "Goh Sek Chye" sekchye@lgatelecom.net To: raphael.coeffic@gmx.de Sent: Monday, January 26, 2004 11:08 AM Subject: sems problem
Hi Raphael,
I am using your voice mail program sems and it is very useful to us. Thank you very much!
However, I have a problem here.
I have a Cisco router 827-4V which is connected to a PBX using FXS port. The Cisco router is configured to point to a SIP server running SER and SEMS.
When a PBX user calls a SIP user who is not online, he hears a long death silence followed by a fast busy tone.
I am clueless what is the problem and would like to seek your help.
The following is the debug message from the SER server and the debug message from the Cisco router. Thanks in advance for your help.
=================
SER debug messages
Jan 26 17:13:41 sip1 ser[25648]: SIP Request: Jan 26 17:13:41 sip1 ser[25648]: method: <INVITE> Jan 26 17:13:41 sip1 ser[25648]: uri:
sip:10650004@192.168.0.222;user=phone
Jan 26 17:13:41 sip1 ser[25648]: version: <SIP/2.0> Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=1 Jan 26 17:13:41 sip1 ser[25648]: end of header reached, state=5 Jan 26 17:13:41 sip1 ser[25648]: parse_headers: Via found, flags=1 Jan 26 17:13:41 sip1 ser[25648]: parse_headers: this is the first via Jan 26 17:13:41 sip1 ser[25648]: After parse_msg... Jan 26 17:13:41 sip1 ser[25648]: preparing to run routing scripts... Jan 26 17:13:41 sip1 ser[25648]: DEBUG : is_maxfwd_present: searching for
max_forwards header
Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=128 Jan 26 17:13:41 sip1 ser[25648]: end of header reached, state=9 Jan 26 17:13:41 sip1 ser[25648]: DEBUG: get_hdr_field: <To> [41];
uri=[sip:10650004@192.168.0.222;user=phone]
Jan 26 17:13:41 sip1 ser[25648]: DEBUG: to body
[sip:10650004@192.168.0.222;user=phone^M ]
Jan 26 17:13:41 sip1 ser[25648]: get_hdr_field: cseq <CSeq>: <101>
<INVITE>
Jan 26 17:13:41 sip1 ser[25648]: DEBUG: is_maxfwd_present: value = 6 Jan 26 17:13:41 sip1 ser[25648]: end of header reached, state=9 Jan 26 17:13:41 sip1 ser[25648]: check_self - checking if host==us: 13==13
&& [192.168.0.222] == [192.168.0.222]
Jan 26 17:13:41 sip1 ser[25648]: lookup(): '10650004' Not found in usrloc Jan 26 17:13:41 sip1 ser[25648]: lookup(): '10650004' Not found in usrloc Jan 26 17:13:41 sip1 ser[25648]: ************************ route[3]:vm:1
*************************************
Jan 26 17:13:41 sip1 ser[25648]: route[3]:vm:2 Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_addifnew: msg id=789 , global
msg id=787 , T on entrance=0xffffffff
Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=-1 Jan 26 17:13:41 sip1 ser[25648]: DEBUG: get_hdr_body : content_length=134 Jan 26 17:13:41 sip1 ser[25648]: found end of header Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=60 Jan 26 17:13:41 sip1 ser[25648]: t_lookup_request: start searching:
hash=43402, isACK=0
Jan 26 17:13:41 sip1 ser[25648]: DEBUG: proceeding to pre-RFC3261
transaction matching
Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_lookup_request: no transaction
found
Jan 26 17:13:41 sip1 ser[25648]: DBG: callback type 2, id 3 entered Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=44 Jan 26 17:13:41 sip1 ser[25648]: DEBUG: noisy_timer set for accounting Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_check: msg id=789 global id=789
T start=0x402e1070
Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_check: T alredy found! Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=-1 Jan 26 17:13:41 sip1 ser[25648]: check_via_address(203.92.75.94,
203.92.75.94, 0)
Jan 26 17:13:41 sip1 ser[25648]: WARNING:vqm_resize: resize(0) called Jan 26 17:13:41 sip1 ser[25648]: DEBUG: reply sent out. buf=0x80d0cd0:
SIP/2.0 1..., shmem=0x402d8cd8: SIP/2.0 1
Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_reply: finished Jan 26 17:13:41 sip1 ser[25648]: route[3]:method==INVITE || REFER Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=-1 Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_check: msg id=789 global id=789
T start=0x402e1070
Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_check: T alredy found! Jan 26 17:13:41 sip1 ser[25648]: vm: calculated route: Jan 26 17:13:41 sip1 ser[25648]: vm: next r-uri:
sip:41703@203.92.75.94:5060;user=phone
Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=-1 Jan 26 17:13:41 sip1 ser[25648]: submit_query(): select email_address from
subscriber where username='10650004'
Jan 26 17:13:41 sip1 ser[25648]: vm: write_to_vm_fifo: <0.1 voicemail
INVITE 10650004 sekchye@yahoo.com 203.92.64
.216 192.168.0.222 5060 sip:10650004@192.168.0.222;user=phone
sip:41703@203.92.75.94:5060;user=phone "41703" <sip
:41703@203.92.75.94>^M sip:10650004@192.168.0.222;user=phone
C475045A-4F1611D8-827089FC-A1038096@203.92.75.94 .
. 101 43402:300376901 . . . v=0^M o=CiscoSystemsSIP-GW-UserAgent 5931
2351 IN IP4 203.92.75.94^M s=SIP Call^M c=
IN IP4 203.92.75.94^M t=0 0^M m=audio 20416 RTP/AVP 0^M > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: write_to_vm_fifo: write completed Jan 26 17:13:41 sip1 ser[25648]: DEBUG: add_to_tail_of_timer[0]:
0x402e11bc
Jan 26 17:13:41 sip1 ser[25648]: receive_msg: cleaning up Jan 26 17:13:41 sip1 Sems[17680]: Debug: version= <0.1> Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.cmd= <voicemail> Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.method= <INVITE> Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.user= <10650004> Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.email= sekchye@yahoo.com Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.domain= <192.168.0.222> Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.dstip= <192.168.0.222> Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.port= <5060> Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.r_uri=
sip:10650004@192.168.0.222;user=phone
Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.from_uri=
sip:41703@203.92.75.94:5060;user=phone
Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.from= <"41703"
Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.to=
<sip:10650004@192.168.0.222;user=phone>
Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.callid=
C475045A-4F1611D8-827089FC-A1038096@203.92.75.94
Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.from_tag= <> Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.to_tag= <> Jan 26 17:13:41 sip1 Sems[17680]: Debug: cseq_str= <101> Jan 26 17:13:41 sip1 Sems[17680]: Debug: cseq= <101>(101) Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.key= <43402:300376901> Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.route= <> Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.next_hop= <> Jan 26 17:13:41 sip1 Sems[17680]: Debug: hdrs: `' Jan 26 17:13:41 sip1 Sems[17680]: Debug: body: `v=0
o=CiscoSystemsSIP-GW-UserAgent 5931 2351 IN IP4 203.92.75.94
s=SIP Call c=IN IP4 203.92.75.94 t=0 0 m=audio 20416 RTP/AVP 0 ' Jan 26 17:13:41 sip1 Sems[17680]: Error: invalid FIFO command:
cmd.from_tag is empty !!!
Jan 26 17:13:48 sip1 ser[25685]: MSILO:clean_silo: cleaning stored
messages - 874200
Jan 26 17:13:48 sip1 ser[25685]: MSILO:clean_silo: cleaning expired
messages
Jan 26 17:13:48 sip1 ser[25685]: submit_query(): delete from silo where
exp_time<=1075108428
Jan 26 17:13:55 sip1 ser[25685]: DEBUG: timer routine:0,tl=0x402e11bc
next=(nil)
Jan 26 17:13:55 sip1 ser[25685]: DEBUG: FR_handler:stop retr. and send
CANCEL (0x402e1070)
Jan 26 17:13:55 sip1 ser[25685]: DEBUG: FR_handler:stop retr. and send
CANCEL (0x402e1070)
Jan 26 17:13:55 sip1 ser[25685]: ->>>>>>>>> T_code=100, new_code=408 Jan 26 17:13:55 sip1 ser[25685]: DBG: callback type 6, id 4 entered Jan 26 17:13:55 sip1 ser[25685]: submit_query(): insert into missed_calls
(from_uri,to_uri,sip_method,i_uri,o_uri
,sip_from,sip_callid,sip_to,sip_status,username,totag,fromtag,time )
values ('sip:41703@203.92.75.94','sip:106500
04@192.168.0.222;user=phone','INVITE','sip:10650004@192.168.0.222;user=phone ','sip:10650004@192.168.0.222;user=ph
one','"41703"
sip:41703@203.92.75.94','C475045A-4F1611D8-827089FC-A1038096@203.92.75.94' ,'<sip:10650004@203.92.
64.216;user=phone>','408 Request
Timeout','10650004','n/a','n/a','2004-01-26 09:13:55')
Jan 26 17:13:55 sip1 ser[25685]: rc_get_seqnbr: couldn't open sequence
file /var/run/radius.seq: Permission denie
d Jan 26 17:13:55 sip1 ser[25685]: DEBUG: relay_reply: branch=0, save=0,
relay=0
Jan 26 17:13:55 sip1 ser[25685]: parse_headers: flags=-1 Jan 26 17:13:55 sip1 ser[25685]: check_via_address(203.92.75.94,
203.92.75.94, 0)
Jan 26 17:13:55 sip1 ser[25685]: DEBUG: reply relayed. buf=0x80cef08:
SIP/2.0 4..., shmem=0x402d47a8: SIP/2.0 4
Jan 26 17:13:55 sip1 ser[25685]: DBG: callback type 7, id 1 entered Jan 26 17:13:55 sip1 ser[25685]: DEBUG: add_to_tail_of_timer[4]:
0x402e1128
Jan 26 17:13:55 sip1 ser[25685]: DEBUG: add_to_tail_of_timer[0]:
0x402e1140
Jan 26 17:13:55 sip1 ser[25685]: DEBUG: final_response_handler : done Jan 26 17:13:55 sip1 ser[25647]: SIP Request: Jan 26 17:13:55 sip1 ser[25647]: method: <ACK> Jan 26 17:13:55 sip1 ser[25647]: uri:
sip:10650004@192.168.0.222;user=phone
Jan 26 17:13:55 sip1 ser[25647]: version: <SIP/2.0> Jan 26 17:13:55 sip1 ser[25647]: parse_headers: flags=1 Jan 26 17:13:55 sip1 ser[25647]: end of header reached, state=5 Jan 26 17:13:55 sip1 ser[25647]: parse_headers: Via found, flags=1 Jan 26 17:13:55 sip1 ser[25647]: parse_headers: this is the first via Jan 26 17:13:55 sip1 ser[25647]: After parse_msg... Jan 26 17:13:55 sip1 ser[25647]: DEBUG : sl_filter_ACK: to late to be a
local ACK!
Jan 26 17:13:55 sip1 ser[25647]: preparing to run routing scripts... Jan 26 17:13:55 sip1 ser[25647]: DEBUG : is_maxfwd_present: searching for
max_forwards header
Jan 26 17:13:55 sip1 ser[25647]: parse_headers: flags=128 Jan 26 17:13:55 sip1 ser[25647]: DEBUG: add_param:
tag=baea774f5e5e7e26323ab05f178242c9-2bd7
Jan 26 17:13:55 sip1 ser[25647]: end of header reached, state=29 Jan 26 17:13:55 sip1 ser[25647]: DEBUG: get_hdr_field: <To> [83];
uri=[sip:10650004@192.168.0.222;user=phone]
Jan 26 17:13:55 sip1 ser[25647]: DEBUG: to body
[sip:10650004@192.168.0.222;user=phone]
Jan 26 17:13:55 sip1 ser[25647]: DEBUG: is_maxfwd_present: value = 6 Jan 26 17:13:55 sip1 ser[25647]: end of header reached, state=9 Jan 26 17:13:55 sip1 ser[25647]: check_self - checking if host==us: 13==13
&& [192.168.0.222] == [192.168.0.222]
Jan 26 17:13:55 sip1 ser[25647]: lookup(): '10650004' Not found in usrloc Jan 26 17:13:55 sip1 ser[25647]: lookup(): '10650004' Not found in usrloc Jan 26 17:13:55 sip1 ser[25647]: ************************ route[3]:vm:1
*************************************
Jan 26 17:13:55 sip1 ser[25647]: receive_msg: cleaning up Jan 26 17:13:56 sip1 ser[25685]: DEBUG: timer routine:4,tl=0x402e1128
next=(nil)
Jan 26 17:13:56 sip1 ser[25685]: DEBUG: retransmission_handler : reply
resending (t=0x402e1070, SIP/2.0 4 ... )
Jan 26 17:13:56 sip1 ser[25685]: DEBUG: reply retransmitted.
buf=0x42237da0: SIP/2.0 4..., shmem=0x402d47a8: SIP/
2.0 4 Jan 26 17:13:56 sip1 ser[25685]: DEBUG: add_to_tail_of_timer[5]:
0x402e1128
Jan 26 17:13:56 sip1 ser[25685]: DEBUG: retransmission_handler : done Jan 26 17:13:58 sip1 ser[25685]: DEBUG: timer routine:5,tl=0x402e1128
next=(nil)
Jan 26 17:13:58 sip1 ser[25685]: DEBUG: retransmission_handler : reply
resending (t=0x402e1070, SIP/2.0 4 ... )
Jan 26 17:13:58 sip1 ser[25685]: DEBUG: reply retransmitted.
buf=0x42237da0: SIP/2.0 4..., shmem=0x402d47a8: SIP/
2.0 4 Jan 26 17:13:58 sip1 ser[25685]: DEBUG: add_to_tail_of_timer[6]:
0x402e1128
Jan 26 17:13:58 sip1 ser[25685]: DEBUG: retransmission_handler : done Jan 26 17:14:02 sip1 ser[25685]: DEBUG: timer routine:6,tl=0x402e1128
next=(nil)
Jan 26 17:14:02 sip1 ser[25685]: DEBUG: retransmission_handler : reply
resending (t=0x402e1070, SIP/2.0 4 ... )
Jan 26 17:14:02 sip1 ser[25685]: DEBUG: reply retransmitted.
buf=0x42237da0: SIP/2.0 4..., shmem=0x402d47a8: SIP/
2.0 4 Jan 26 17:14:02 sip1 ser[25685]: DEBUG: add_to_tail_of_timer[7]:
0x402e1128
Jan 26 17:14:02 sip1 ser[25685]: DEBUG: retransmission_handler : done Jan 26 17:14:06 sip1 ser[25685]: DEBUG: timer routine:7,tl=0x402e1128
next=(nil)
Jan 26 17:14:06 sip1 ser[25685]: DEBUG: retransmission_handler : reply
resending (t=0x402e1070, SIP/2.0 4 ... )
Jan 26 17:14:06 sip1 ser[25685]: DEBUG: reply retransmitted.
buf=0x42237da0: SIP/2.0 4..., shmem=0x402d47a8: SIP/
2.0 4 Jan 26 17:14:06 sip1 ser[25685]: DEBUG: add_to_tail_of_timer[7]:
0x402e1128
Jan 26 17:14:06 sip1 ser[25685]: DEBUG: retransmission_handler : done Jan 26 17:14:10 sip1 ser[25685]: DEBUG: timer routine:0,tl=0x402e1140
next=(nil)
Debug message from Cisco 827-V router
Jan 26 17:13:41.158 SGT: Sent: INVITE sip:10650004@192.168.0.222;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.202:5060 From: "41703" sip:41703@192.168.0.202 To: sip:10650004@192.168.0.222;user=phone Date: Mon, 26 Jan 2004 17:13:41 GMT Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 Cisco-Guid: 3162002760-1326846424-2188282364-2701361302 User-Agent: Cisco-SIPGateway/IOS-12.x CSeq: 101 INVITE Max-Forwards: 6 Timestamp: 1075108421 Contact: sip:41703@192.168.0.202:5060;user=phone Expires: 180 Content-Type: application/sdp Content-Length: 136
v=0 o=CiscoSystemsSIP-GW-UserAgent 5931 2351 IN IP4 192.168.0.202 s=SIP Call c=IN IP4 192.168.0.202 t=0 0 m=audio 20416 RTP/AVP 0
Jan 26 17:13:41.170 SGT: Received: SIP/2.0 100 Trying -- just a second Via: SIP/2.0/UDP 192.168.0.202:5060 From: "41703" sip:41703@192.168.0.202 To: sip:10650004@192.168.0.222;user=phone Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 CSeq: 101 INVITE Server: Sip EXpress router (0.8.11 (i386/linux)) Content-Length: 0
Jan 26 17:13:55.338 SGT: Received: SIP/2.0 408 Request Timeout Via: SIP/2.0/UDP 192.168.0.202:5060 From: "41703" sip:41703@192.168.0.202 To:
sip:10650004@192.168.0.222;user=phone;tag=baea774f5e5e7e26323ab05f178242c9 -2bd7
Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 CSeq: 101 INVITE Server: Sip EXpress router (0.8.11 (i386/linux)) Content-Length: 0
Jan 26 17:13:55.358 SGT: Sent: ACK sip:10650004@192.168.0.222;user=phone SIP/2.0 Via: SIP/2.0/UDP 192.168.0.202:5060 From: "41703" sip:41703@192.168.0.202 To:
sip:10650004@192.168.0.222;user=phone;tag=baea774f5e5e7e26323ab05f178242c9 -2bd7
Date: Mon, 26 Jan 2004 17:13:41 GMT Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 Max-Forwards: 6 Content-Length: 0 CSeq: 101 ACK
Jan 26 17:13:56.346 SGT: Received: SIP/2.0 408 Request Timeout Via: SIP/2.0/UDP 192.168.0.202:5060 From: "41703" sip:41703@192.168.0.202 To:
sip:10650004@192.168.0.222;user=phone;tag=baea774f5e5e7e26323ab05f178242c9 -2bd7
Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 CSeq: 101 INVITE Server: Sip EXpress router (0.8.11 (i386/linux)) Content-Length: 0
Jan 26 17:14:02.406 SGT: Received: SIP/2.0 408 Request Timeout Via: SIP/2.0/UDP 192.168.0.202:5060 From: "41703" sip:41703@192.168.0.202 To:
sip:10650004@192.168.0.222;user=phone;tag=baea774f5e5e7e26323ab05f178242c9 -2bd7
Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 CSeq: 101 INVITE Server: Sip EXpress router (0.8.11 (i386/linux)) Content-Length: 0
Jan 26 17:14:06.446 SGT: Received: SIP/2.0 408 Request Timeout Via: SIP/2.0/UDP 192.168.0.202:5060 From: "41703" sip:41703@192.168.0.202 To:
sip:10650004@192.168.0.222;user=phone;tag=baea774f5e5e7e26323ab05f178242c9 -2bd7
Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 CSeq: 101 INVITE Server: Sip EXpress router (0.8.11 (i386/linux)) Content-Length: 0
-- Best regards Goh Sek Chye LGA Telecom Pte Ltd PGP KeyID: AE6D04A2
PS: To import my PGP key, gpg --recv-keys --keyserver wwwkeys.pgp.net AE6D04A2
Privileged, confidential and/or copyright information may be contained in this e-mail. This e-mail is for the use only of the intended addressee. If you are not the intended addressee, or the person responsible for delivering it to the intended addressee, you may not copy, forward, disclose or otherwise use it or any part of it in any way whatsoever. To do so is prohibited and may be unlawful. If you receive this e-mail by mistake please advise the sender immediately by using the reply facility in your e-mail software. This message is subject to and does not create or vary any contractual relationship between Little Green Apples Pte Ltd (the Company) or any of its subsidiaries (comprising of LGA Technologies Pte Ltd; LGA International Pte Ltd; & LGA Telecom Pte Ltd) and you. By opening any attachment to this message, you also agree to accept the risk that it may contain a virus or damaging code, and you agree that the sender and/or the Company and its subsidiaries will not be liable for any loss or damage thereby caused.
Hi there!
Thanks for your response. In this case, I will trying changing the router software and see whether it will fix the problem.
I will update you once I have any findings. Thanks!
On Wed, Jan 28, 2004 at 12:04:06PM +0100, Raphael Coeffic wrote:
Hello,
it seems like that Cisco 827-V router doesn't include any from-tag within its INVITEs...which is NOT RFC CONFORM!. It may be due to some kind of proprietary function mode. There is nothing we can do on the SEMS side to solve the problem.
Does anybody else have such a gateway and got it work with voicemail?
-Raphael.
----- Original Message ----- From: "Goh Sek Chye" sekchye@lgatelecom.net To: raphael.coeffic@gmx.de Sent: Monday, January 26, 2004 11:08 AM Subject: sems problem
Hi Raphael,
I am using your voice mail program sems and it is very useful to us. Thank you very much!
However, I have a problem here.
I have a Cisco router 827-4V which is connected to a PBX using FXS port. The Cisco router is configured to point to a SIP server running SER and SEMS.
When a PBX user calls a SIP user who is not online, he hears a long death silence followed by a fast busy tone.
I am clueless what is the problem and would like to seek your help.
The following is the debug message from the SER server and the debug message from the Cisco router. Thanks in advance for your help.
=================
SER debug messages
Jan 26 17:13:41 sip1 ser[25648]: SIP Request: Jan 26 17:13:41 sip1 ser[25648]: method: <INVITE> Jan 26 17:13:41 sip1 ser[25648]: uri:
sip:10650004@192.168.0.222;user=phone
Jan 26 17:13:41 sip1 ser[25648]: version: <SIP/2.0> Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=1 Jan 26 17:13:41 sip1 ser[25648]: end of header reached, state=5 Jan 26 17:13:41 sip1 ser[25648]: parse_headers: Via found, flags=1 Jan 26 17:13:41 sip1 ser[25648]: parse_headers: this is the first via Jan 26 17:13:41 sip1 ser[25648]: After parse_msg... Jan 26 17:13:41 sip1 ser[25648]: preparing to run routing scripts... Jan 26 17:13:41 sip1 ser[25648]: DEBUG : is_maxfwd_present: searching for
max_forwards header
Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=128 Jan 26 17:13:41 sip1 ser[25648]: end of header reached, state=9 Jan 26 17:13:41 sip1 ser[25648]: DEBUG: get_hdr_field: <To> [41];
uri=[sip:10650004@192.168.0.222;user=phone]
Jan 26 17:13:41 sip1 ser[25648]: DEBUG: to body
[sip:10650004@192.168.0.222;user=phone^M ]
Jan 26 17:13:41 sip1 ser[25648]: get_hdr_field: cseq <CSeq>: <101>
<INVITE> > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: is_maxfwd_present: value = 6 > Jan 26 17:13:41 sip1 ser[25648]: end of header reached, state=9 > Jan 26 17:13:41 sip1 ser[25648]: check_self - checking if host==us: 13==13 && [192.168.0.222] == [192.168.0.222] > > Jan 26 17:13:41 sip1 ser[25648]: lookup(): '10650004' Not found in usrloc > Jan 26 17:13:41 sip1 ser[25648]: lookup(): '10650004' Not found in usrloc > Jan 26 17:13:41 sip1 ser[25648]: ************************ route[3]:vm:1 ************************************* > Jan 26 17:13:41 sip1 ser[25648]: route[3]:vm:2 > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_addifnew: msg id=789 , global msg id=787 , T on entrance=0xffffffff > Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=-1 > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: get_hdr_body : content_length=134 > Jan 26 17:13:41 sip1 ser[25648]: found end of header > Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=60 > Jan 26 17:13:41 sip1 ser[25648]: t_lookup_request: start searching: hash=43402, isACK=0 > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: proceeding to pre-RFC3261 transaction matching > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_lookup_request: no transaction found > Jan 26 17:13:41 sip1 ser[25648]: DBG: callback type 2, id 3 entered > Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=44 > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: noisy_timer set for accounting > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_check: msg id=789 global id=789 T start=0x402e1070 > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_check: T alredy found! > Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=-1 > Jan 26 17:13:41 sip1 ser[25648]: check_via_address(203.92.75.94, 203.92.75.94, 0) > Jan 26 17:13:41 sip1 ser[25648]: WARNING:vqm_resize: resize(0) called > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: reply sent out. buf=0x80d0cd0: SIP/2.0 1..., shmem=0x402d8cd8: SIP/2.0 1 > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_reply: finished > Jan 26 17:13:41 sip1 ser[25648]: route[3]:method==INVITE || REFER > Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=-1 > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_check: msg id=789 global id=789 T start=0x402e1070 > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: t_check: T alredy found! > Jan 26 17:13:41 sip1 ser[25648]: vm: calculated route: > Jan 26 17:13:41 sip1 ser[25648]: vm: next r-uri: sip:41703@203.92.75.94:5060;user=phone > Jan 26 17:13:41 sip1 ser[25648]: parse_headers: flags=-1 > Jan 26 17:13:41 sip1 ser[25648]: submit_query(): select email_address from subscriber where username='10650004' > Jan 26 17:13:41 sip1 ser[25648]: vm: write_to_vm_fifo: <0.1 voicemail INVITE 10650004 sekchye@yahoo.com 203.92.64 > .216 192.168.0.222 5060 sip:10650004@192.168.0.222;user=phone sip:41703@203.92.75.94:5060;user=phone "41703" <sip > :41703@203.92.75.94>^M <sip:10650004@192.168.0.222;user=phone> C475045A-4F1611D8-827089FC-A1038096@203.92.75.94 . > . 101 43402:300376901 . . . v=0^M o=CiscoSystemsSIP-GW-UserAgent 5931 2351 IN IP4 203.92.75.94^M s=SIP Call^M c= > IN IP4 203.92.75.94^M t=0 0^M m=audio 20416 RTP/AVP 0^M > > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: write_to_vm_fifo: write completed > Jan 26 17:13:41 sip1 ser[25648]: DEBUG: add_to_tail_of_timer[0]: 0x402e11bc > Jan 26 17:13:41 sip1 ser[25648]: receive_msg: cleaning up > Jan 26 17:13:41 sip1 Sems[17680]: Debug: version= <0.1> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.cmd= <voicemail> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.method= <INVITE> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.user= <10650004> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.email= <sekchye@yahoo.com> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.domain= <192.168.0.222> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.dstip= <192.168.0.222> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.port= <5060> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.r_uri= <sip:10650004@192.168.0.222;user=phone> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.from_uri= <sip:41703@203.92.75.94:5060;user=phone> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.from= <"41703" <sip:41703@203.92.75.94>> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.to= <<sip:10650004@192.168.0.222;user=phone>> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.callid= <C475045A-4F1611D8-827089FC-A1038096@203.92.75.94> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.from_tag= <> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.to_tag= <> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cseq_str= <101> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cseq= <101>(101) > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.key= <43402:300376901> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.route= <> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: cmd.next_hop= <> > Jan 26 17:13:41 sip1 Sems[17680]: Debug: hdrs: `' > Jan 26 17:13:41 sip1 Sems[17680]: Debug: body: `v=0 o=CiscoSystemsSIP-GW-UserAgent 5931 2351 IN IP4 203.92.75.94 > s=SIP Call c=IN IP4 203.92.75.94 t=0 0 m=audio 20416 RTP/AVP 0 ' > Jan 26 17:13:41 sip1 Sems[17680]: Error: invalid FIFO command: cmd.from_tag is empty !!! > Jan 26 17:13:48 sip1 ser[25685]: MSILO:clean_silo: cleaning stored messages - 874200 > Jan 26 17:13:48 sip1 ser[25685]: MSILO:clean_silo: cleaning expired messages > Jan 26 17:13:48 sip1 ser[25685]: submit_query(): delete from silo where exp_time<=1075108428 > Jan 26 17:13:55 sip1 ser[25685]: DEBUG: timer routine:0,tl=0x402e11bc next=(nil) > Jan 26 17:13:55 sip1 ser[25685]: DEBUG: FR_handler:stop retr. and send CANCEL (0x402e1070) > Jan 26 17:13:55 sip1 ser[25685]: DEBUG: FR_handler:stop retr. and send CANCEL (0x402e1070) > Jan 26 17:13:55 sip1 ser[25685]: ->>>>>>>>> T_code=100, new_code=408 > Jan 26 17:13:55 sip1 ser[25685]: DBG: callback type 6, id 4 entered > Jan 26 17:13:55 sip1 ser[25685]: submit_query(): insert into missed_calls (from_uri,to_uri,sip_method,i_uri,o_uri > ,sip_from,sip_callid,sip_to,sip_status,username,totag,fromtag,time ) values ('sip:41703@203.92.75.94','sip:106500 > 04@192.168.0.222;user=phone','INVITE','sip:10650004@192.168.0.222;user=phone ','sip:10650004@192.168.0.222;user=ph > one','"41703" <sip:41703@203.92.75.94>','C475045A-4F1611D8-827089FC-A1038096@203.92.75.94' ,'<sip:10650004@203.92. > 64.216;user=phone>','408 Request Timeout','10650004','n/a','n/a','2004-01-26 09:13:55') > Jan 26 17:13:55 sip1 ser[25685]: rc_get_seqnbr: couldn't open sequence file /var/run/radius.seq: Permission denie > d > Jan 26 17:13:55 sip1 ser[25685]: DEBUG: relay_reply: branch=0, save=0, relay=0 > Jan 26 17:13:55 sip1 ser[25685]: parse_headers: flags=-1 > Jan 26 17:13:55 sip1 ser[25685]: check_via_address(203.92.75.94, 203.92.75.94, 0) > Jan 26 17:13:55 sip1 ser[25685]: DEBUG: reply relayed. buf=0x80cef08: SIP/2.0 4..., shmem=0x402d47a8: SIP/2.0 4 > Jan 26 17:13:55 sip1 ser[25685]: DBG: callback type 7, id 1 entered > Jan 26 17:13:55 sip1 ser[25685]: DEBUG: add_to_tail_of_timer[4]: 0x402e1128 > Jan 26 17:13:55 sip1 ser[25685]: DEBUG: add_to_tail_of_timer[0]: 0x402e1140 > Jan 26 17:13:55 sip1 ser[25685]: DEBUG: final_response_handler : done > Jan 26 17:13:55 sip1 ser[25647]: SIP Request: > Jan 26 17:13:55 sip1 ser[25647]: method: <ACK> > Jan 26 17:13:55 sip1 ser[25647]: uri: <sip:10650004@192.168.0.222;user=phone> > Jan 26 17:13:55 sip1 ser[25647]: version: <SIP/2.0> > Jan 26 17:13:55 sip1 ser[25647]: parse_headers: flags=1 > Jan 26 17:13:55 sip1 ser[25647]: end of header reached, state=5 > Jan 26 17:13:55 sip1 ser[25647]: parse_headers: Via found, flags=1 > Jan 26 17:13:55 sip1 ser[25647]: parse_headers: this is the first via > Jan 26 17:13:55 sip1 ser[25647]: After parse_msg... > Jan 26 17:13:55 sip1 ser[25647]: DEBUG : sl_filter_ACK: to late to be a local ACK! > Jan 26 17:13:55 sip1 ser[25647]: preparing to run routing scripts... > Jan 26 17:13:55 sip1 ser[25647]: DEBUG : is_maxfwd_present: searching for max_forwards header > Jan 26 17:13:55 sip1 ser[25647]: parse_headers: flags=128 > Jan 26 17:13:55 sip1 ser[25647]: DEBUG: add_param: tag=baea774f5e5e7e26323ab05f178242c9-2bd7 > Jan 26 17:13:55 sip1 ser[25647]: end of header reached, state=29 > Jan 26 17:13:55 sip1 ser[25647]: DEBUG: get_hdr_field: <To> [83]; uri=[sip:10650004@192.168.0.222;user=phone] > Jan 26 17:13:55 sip1 ser[25647]: DEBUG: to body [<sip:10650004@192.168.0.222;user=phone>] > Jan 26 17:13:55 sip1 ser[25647]: DEBUG: is_maxfwd_present: value = 6 > Jan 26 17:13:55 sip1 ser[25647]: end of header reached, state=9 > Jan 26 17:13:55 sip1 ser[25647]: check_self - checking if host==us: 13==13 && [192.168.0.222] == [192.168.0.222] > > Jan 26 17:13:55 sip1 ser[25647]: lookup(): '10650004' Not found in usrloc > Jan 26 17:13:55 sip1 ser[25647]: lookup(): '10650004' Not found in usrloc > Jan 26 17:13:55 sip1 ser[25647]: ************************ route[3]:vm:1 ************************************* > Jan 26 17:13:55 sip1 ser[25647]: receive_msg: cleaning up > Jan 26 17:13:56 sip1 ser[25685]: DEBUG: timer routine:4,tl=0x402e1128 next=(nil) > Jan 26 17:13:56 sip1 ser[25685]: DEBUG: retransmission_handler : reply resending (t=0x402e1070, SIP/2.0 4 ... ) > Jan 26 17:13:56 sip1 ser[25685]: DEBUG: reply retransmitted. buf=0x42237da0: SIP/2.0 4..., shmem=0x402d47a8: SIP/ > 2.0 4 > Jan 26 17:13:56 sip1 ser[25685]: DEBUG: add_to_tail_of_timer[5]: 0x402e1128 > Jan 26 17:13:56 sip1 ser[25685]: DEBUG: retransmission_handler : done > Jan 26 17:13:58 sip1 ser[25685]: DEBUG: timer routine:5,tl=0x402e1128 next=(nil) > Jan 26 17:13:58 sip1 ser[25685]: DEBUG: retransmission_handler : reply resending (t=0x402e1070, SIP/2.0 4 ... ) > Jan 26 17:13:58 sip1 ser[25685]: DEBUG: reply retransmitted. buf=0x42237da0: SIP/2.0 4..., shmem=0x402d47a8: SIP/ > 2.0 4 > Jan 26 17:13:58 sip1 ser[25685]: DEBUG: add_to_tail_of_timer[6]: 0x402e1128 > Jan 26 17:13:58 sip1 ser[25685]: DEBUG: retransmission_handler : done > Jan 26 17:14:02 sip1 ser[25685]: DEBUG: timer routine:6,tl=0x402e1128 next=(nil) > Jan 26 17:14:02 sip1 ser[25685]: DEBUG: retransmission_handler : reply resending (t=0x402e1070, SIP/2.0 4 ... ) > Jan 26 17:14:02 sip1 ser[25685]: DEBUG: reply retransmitted. buf=0x42237da0: SIP/2.0 4..., shmem=0x402d47a8: SIP/ > 2.0 4 > Jan 26 17:14:02 sip1 ser[25685]: DEBUG: add_to_tail_of_timer[7]: 0x402e1128 > Jan 26 17:14:02 sip1 ser[25685]: DEBUG: retransmission_handler : done > Jan 26 17:14:06 sip1 ser[25685]: DEBUG: timer routine:7,tl=0x402e1128 next=(nil) > Jan 26 17:14:06 sip1 ser[25685]: DEBUG: retransmission_handler : reply resending (t=0x402e1070, SIP/2.0 4 ... ) > Jan 26 17:14:06 sip1 ser[25685]: DEBUG: reply retransmitted. buf=0x42237da0: SIP/2.0 4..., shmem=0x402d47a8: SIP/ > 2.0 4 > Jan 26 17:14:06 sip1 ser[25685]: DEBUG: add_to_tail_of_timer[7]: 0x402e1128 > Jan 26 17:14:06 sip1 ser[25685]: DEBUG: retransmission_handler : done > Jan 26 17:14:10 sip1 ser[25685]: DEBUG: timer routine:0,tl=0x402e1140 next=(nil) > > > > > > > > > > Debug message from Cisco 827-V router > ===================================== > Jan 26 17:13:41.158 SGT: Sent: > INVITE sip:10650004@192.168.0.222;user=phone SIP/2.0 > Via: SIP/2.0/UDP 192.168.0.202:5060 > From: "41703" <sip:41703@192.168.0.202> > To: <sip:10650004@192.168.0.222;user=phone> > Date: Mon, 26 Jan 2004 17:13:41 GMT > Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 > Cisco-Guid: 3162002760-1326846424-2188282364-2701361302 > User-Agent: Cisco-SIPGateway/IOS-12.x > CSeq: 101 INVITE > Max-Forwards: 6 > Timestamp: 1075108421 > Contact: <sip:41703@192.168.0.202:5060;user=phone> > Expires: 180 > Content-Type: application/sdp > Content-Length: 136 > > v=0 > o=CiscoSystemsSIP-GW-UserAgent 5931 2351 IN IP4 192.168.0.202 > s=SIP Call > c=IN IP4 192.168.0.202 > t=0 0 > m=audio 20416 RTP/AVP 0 > > Jan 26 17:13:41.170 SGT: Received: > SIP/2.0 100 Trying -- just a second > Via: SIP/2.0/UDP 192.168.0.202:5060 > From: "41703" <sip:41703@192.168.0.202> > To: <sip:10650004@192.168.0.222;user=phone> > Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 > CSeq: 101 INVITE > Server: Sip EXpress router (0.8.11 (i386/linux)) > Content-Length: 0 > > > > Jan 26 17:13:55.338 SGT: Received: > SIP/2.0 408 Request Timeout > Via: SIP/2.0/UDP 192.168.0.202:5060 > From: "41703" <sip:41703@192.168.0.202> > To: <sip:10650004@192.168.0.222;user=phone>;tag=baea774f5e5e7e26323ab05f178242c9 -2bd7 > Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 > CSeq: 101 INVITE > Server: Sip EXpress router (0.8.11 (i386/linux)) > Content-Length: 0 > > > > Jan 26 17:13:55.358 SGT: Sent: > ACK sip:10650004@192.168.0.222;user=phone SIP/2.0 > Via: SIP/2.0/UDP 192.168.0.202:5060 > From: "41703" <sip:41703@192.168.0.202> > To: <sip:10650004@192.168.0.222;user=phone>;tag=baea774f5e5e7e26323ab05f178242c9 -2bd7 > Date: Mon, 26 Jan 2004 17:13:41 GMT > Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 > Max-Forwards: 6 > Content-Length: 0 > CSeq: 101 ACK > > > > Jan 26 17:13:56.346 SGT: Received: > SIP/2.0 408 Request Timeout > Via: SIP/2.0/UDP 192.168.0.202:5060 > From: "41703" <sip:41703@192.168.0.202> > To: <sip:10650004@192.168.0.222;user=phone>;tag=baea774f5e5e7e26323ab05f178242c9 -2bd7 > Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 > CSeq: 101 INVITE > Server: Sip EXpress router (0.8.11 (i386/linux)) > Content-Length: 0 > > > > > Jan 26 17:14:02.406 SGT: Received: > SIP/2.0 408 Request Timeout > Via: SIP/2.0/UDP 192.168.0.202:5060 > From: "41703" <sip:41703@192.168.0.202> > To: <sip:10650004@192.168.0.222;user=phone>;tag=baea774f5e5e7e26323ab05f178242c9 -2bd7 > Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 > CSeq: 101 INVITE > Server: Sip EXpress router (0.8.11 (i386/linux)) > Content-Length: 0 > > > > Jan 26 17:14:06.446 SGT: Received: > SIP/2.0 408 Request Timeout > Via: SIP/2.0/UDP 192.168.0.202:5060 > From: "41703" <sip:41703@192.168.0.202> > To: <sip:10650004@192.168.0.222;user=phone>;tag=baea774f5e5e7e26323ab05f178242c9 -2bd7 > Call-ID: C475045A-4F1611D8-827089FC-A1038096@192.168.0.202 > CSeq: 101 INVITE > Server: Sip EXpress router (0.8.11 (i386/linux)) > Content-Length: 0 > > > > > > > > > > > > > > > >
-
Raphael Coeffic -
sekchye＠yahoo.com