29 Jan
2004
29 Jan
'04
4 a.m.
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(a)lgatelecom.net>
To: <raphael.coeffic(a)gmx.de>
Sent: Monday, January 26, 2004 11:08 AM
Subject: sems problem
04@192.168.0.222;user=phone','INVITE','sip:10650004@192.168.0.222;user=phone
','sip:10650004@192.168.0.222;user=ph
> 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
*************************************
> 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(a)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(a)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(a)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(a)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(a)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(a)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(a)192.168.0.202
> CSeq: 101 INVITE
> Server: Sip EXpress router (0.8.11 (i386/linux))
> Content-Length: 0
>
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(a)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(a)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(a)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(a)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
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]: 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)