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 > > > > > > > > > > > > > > > >