[Serusers] Is SER doc PSTN Gateway example incomplete/incompatible with Asterisk?
Frank Durda IV
frank.durda at hypercube-llc.com
Wed Feb 6 18:52:22 CET 2008
Hello,
I am working my way through the "SER - Getting Started" documentation,
using the sample configurations largely unchanged, and have run up
against something that apparently others have also encountered,
but I have not come across an actual fix for the problem.
The basic lab setup here is
SIP_Phone -> Asterisk_box -> SER_box -> Telica/Lucent LCS switch -> POTS
All IP addresses are 192.168.x.x or 10.x.x.x addresses, with no NATing
being performed. Asterisk and SER are operating on separate
computers.
The goal right now is to originate a call from the SIP phone and
have a POTS phone ring answer on the other side of the LCS switch.
The ser.cfg is essentially the one on page 49 of the "SER Getting
Started" manual, with the local IP addresses substituted.
However, any message received from the Asterisk server results in a
"483 Too Many Hops" error.
As mentioned in lots other places that Google can find, the
Asterisk system fails to include some items that the RFC say should
(or must) be there, and so SER promptly fails. The question is
how to work around this, as in real life I won't have control
of the Asterisk boxes communicating with my SER server and so
can't patch Asterisk to play well with others. So the accommodation
has to be in SER, or more likely, in its config file.
Here is an OPTIONS that are regularly generated by Asterisk, and what
happens to it when SER sees it:
OPTIONS sip:192.168.200.30 SIP/2.0
Via: SIP/2.0/UDP 192.168.200.10:5060;branch=z9hG4bK239aa8ac;rport
From: "asterisk" <sip:asterisk at 192.168.200.10>;tag=as0e01f6d8
To: <sip:192.168.200.30>
Contact: <sip:asterisk at 192.168.200.10>
Call-ID: 74f1aaf801a2f3d750d053e82951e1a5 at 192.168.200.10
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX
Max-Forwards: 70
Date: Tue, 05 Feb 2008 13:24:09 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: SIP Request:
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: method: <OPTIONS>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: uri: <sip:192.168.200.30>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: version: <SIP/2.0>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: flags=1 (HDR_VIA)
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK0d36c05d>; state=6
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 235, <rport> = <n/a>; state=17
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=1
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: this is the first via
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: After parse_msg...
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: preparing to run routing scripts...
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: flags=128 (HDR_ROUTE)
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=9
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: DEBUG: get_hdr_field: <To> [22]; uri=[sip:192.168.200.30]
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: DEBUG: to body [<sip:192.168.200.30> ]
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: get_hdr_field: cseq <CSeq>: <102> <OPTIONS>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: DEBUG:maxfwd:is_maxfwd_present: value = 70
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: DBG:maxfwd:process_maxfwd_header: value 70 decreased to 16
This is the first unexpected behavior. SER apparently silently overrides the hop count
specified by the message source (70) down to 16. Not a big deal, but in complex
networks 16 might not be enough. Anyway, on to what happens...
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: DEBUG: add_param: tag=as2f96b7fd
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=29
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: flags=256 (HDR_RECORDROUTE)
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: DEBUG: get_hdr_body : content_length=0
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: found end of header
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: find_first_route: No Route headers found
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: loose_route: There is no Route HF
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: is_local(): Realm '192.168.200.30' is not local
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: is_local(): Realm '192.168.200.10' is local
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: DEBUG: t_newtran: msg id=449 , global msg id=448 , T on entrance=0xffffffff
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: flags=-1 (HDR_EOH)
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: flags=60 (HDR_INVITE|HDR_INFO|HDR_CANCEL|HDR_BYE)
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: t_lookup_request: start searching: hash=3507, isACK=0
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: DEBUG: RFC3261 transaction matching failed
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: DEBUG: t_lookup_request: no transaction found
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: DEBUG: mk_proxy: doing DNS lookup...
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: check_via_address(192.168.200.10, 192.168.200.10, 0)
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: SIP Request:
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: method: <OPTIONS>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: uri: <sip:192.168.200.30>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: version: <SIP/2.0>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: parse_headers: flags=1
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: Found param type 232, <branch> = <z9hG4bK3bd.ca3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: parse_headers: Via found, flags=1
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: parse_headers: this is the first via
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: After parse_msg...
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: preparing to run routing scripts...
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: parse_headers: flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: Found param type 232, <branch> = <z9hG4bK0d36c05d>; state=6
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: Found param type 235, <rport> = <5060>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: parse_headers: this is the second via
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: end of header reached, state=9
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: DEBUG: get_hdr_field: <To> [22]; uri=[sip:192.168.200.30]
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: DEBUG: to body [<sip:192.168.200.30> ]
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: get_hdr_field: cseq <CSeq>: <102> <OPTIONS>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: DEBUG:maxfwd:is_maxfwd_present: value = 16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: DEBUG: add_param: tag=as2f96b7fd
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: end of header reached, state=29
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: parse_headers: flags=256
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: DEBUG: get_hdr_body : content_length=0
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: found end of header
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: find_first_route: No Route headers found
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: loose_route: There is no Route HF
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: DEBUG: add_to_tail_of_timer[4]: 0x284eb508
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: DEBUG: add_to_tail_of_timer[0]: 0x284eb518
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: SER: new transaction fwd'ed
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: DEBUG:destroy_avp_list: destroying list 0x0
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: receive_msg: cleaning up
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: is_local(): Realm '192.168.200.30' is not local
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: is_local(): Realm '192.168.200.10' is local
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: DEBUG: t_newtran: msg id=454 , global msg id=453 , T on entrance=0xffffffff
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: parse_headers: flags=-1
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: parse_headers: flags=60
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: t_lookup_request: start searching: hash=3507, isACK=0
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: DEBUG: RFC3261 transaction matching failed
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: DEBUG: t_lookup_request: no transaction found
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: DEBUG: mk_proxy: doing DNS lookup...
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: check_via_address(192.168.200.30, 192.168.200.30, 0)
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: DEBUG: add_to_tail_of_timer[4]: 0x284eccd0
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: DEBUG: add_to_tail_of_timer[0]: 0x284ecce0
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: SER: new transaction fwd'ed
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: DEBUG:destroy_avp_list: destroying list 0x0
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1041]: receive_msg: cleaning up
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: SIP Request:
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: method: <OPTIONS>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: uri: <sip:192.168.200.30>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: version: <SIP/2.0>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: parse_headers: flags=1
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: Found param type 232, <branch> = <z9hG4bK3bd.da3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: parse_headers: Via found, flags=1
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: parse_headers: this is the first via
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: After parse_msg...
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: preparing to run routing scripts...
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: parse_headers: flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: Found param type 232, <branch> = <z9hG4bK3bd.ca3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: parse_headers: this is the second via
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: Found param type 232, <branch> = <z9hG4bK0d36c05d>; state=6
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: Found param type 235, <rport> = <5060>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: end of header reached, state=9
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: DEBUG: get_hdr_field: <To> [22]; uri=[sip:192.168.200.30]
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: DEBUG: to body [<sip:192.168.200.30> ]
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: get_hdr_field: cseq <CSeq>: <102> <OPTIONS>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: DEBUG:maxfwd:is_maxfwd_present: value = 15
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: DEBUG: add_param: tag=as2f96b7fd
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: end of header reached, state=29
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: parse_headers: flags=256
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: DEBUG: get_hdr_body : content_length=0
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: found end of header
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: find_first_route: No Route headers found
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: loose_route: There is no Route HF
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: is_local(): Realm '192.168.200.30' is not local
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: is_local(): Realm '192.168.200.10' is local
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: DEBUG: t_newtran: msg id=454 , global msg id=453 , T on entrance=0xffffffff
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: parse_headers: flags=-1
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: parse_headers: flags=60
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: t_lookup_request: start searching: hash=3507, isACK=0
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: DEBUG: RFC3261 transaction matching failed
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: DEBUG: t_lookup_request: no transaction found
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: DEBUG: mk_proxy: doing DNS lookup...
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1040]: check_via_address(192.168.200.30, 192.168.200.30, 0)
... waiting for the hop counter to decrement to zero...
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: SIP Request:
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: method: <OPTIONS>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: uri: <sip:192.168.200.30>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: version: <SIP/2.0>
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: flags=1
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.bb3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=1
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: this is the first via
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: After parse_msg...
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: preparing to run routing scripts...
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.ab3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: this is the second via
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.9b3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.8b3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.7b3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.6b3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.5b3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.4b3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.3b3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.2b3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.1b3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.0b3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.fa3aab21.0>; state=16
Feb 5 15:02:43 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.ea3aab21.0>; state=16
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.da3aab21.0>; state=16
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.ca3aab21.0>; state=16
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK0d36c05d>; state=6
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: Found param type 235, <rport> = <5060>; state=16
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=128
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=9
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: DEBUG: get_hdr_field: <To> [22]; uri=[sip:192.168.200.30]
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: DEBUG: to body [<sip:192.168.200.30>^M ]
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: get_hdr_field: cseq <CSeq>: <102> <OPTIONS>
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: DEBUG:maxfwd:is_maxfwd_present: value = 1
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: DEBUG: add_param: tag=as2f96b7fd
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=29
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: parse_headers: flags=256
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: DEBUG: get_hdr_body : content_length=0
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: found end of header
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: find_first_route: No Route headers found
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: loose_route: There is no Route HF
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: is_local(): Realm '192.168.200.30' is not local
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: is_local(): Realm '192.168.200.10' is local
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: DEBUG: t_newtran: msg id=453 , global msg id=452 , T on entrance=0xffffffff
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: parse_headers: flags=-1
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: parse_headers: flags=60
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: t_lookup_request: start searching: hash=3507, isACK=0
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: DEBUG: RFC3261 transaction matching failed
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: DEBUG: t_lookup_request: no transaction found
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: DEBUG: mk_proxy: doing DNS lookup...
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: check_via_address(192.168.200.30, 192.168.200.30, 0)
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: DEBUG: add_to_tail_of_timer[4]: 0x28510828
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: DEBUG: add_to_tail_of_timer[0]: 0x28510838
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: SER: new transaction fwd'ed
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: DEBUG:destroy_avp_list: destroying list 0x0
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: receive_msg: cleaning up
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: SIP Reply (status):
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: version: <SIP/2.0>
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: status: <483>
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: reason: <Too Many Hops>
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: parse_headers: flags=1
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: Found param type 232, <branch> = <z9hG4bK3bd.ab3aab21.0>; state=16
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: end of header reached, state=5
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: parse_headers: Via found, flags=1
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: parse_headers: this is the first via
Feb 5 15:02:44 ser1 /usr/local/sbin/ser[1039]: After parse_msg...
...
So the hop counter reaches zero and the activity ends with a 438 Too Many Hops error
being returned. None of this appears to have made it past the SER system, so I don't
believe the LCS (acting as PSTN gateway) got involved at all.
The problem appears to circle around the lack of a Route: or Record-Route: and/or
a lack or "lr" in the message. INVITE and other message types fail in the same
way, so nothing gets started at all.
In searching around, I came across a reference to adding this piece of code to
the start of route[1]
[-]# A note on when we need to call lookup("location")
[-]#
[-]# This was posted to serusers on 02/23/2005 by Daniel-Constantin Mierla
[-]#
[-]# lookup("location") has to be used for any request that has the domain
[-]# part of R-URI pointing to your SIP server, should be delivered to an
[-]# end-user and does not have to follow any Route header -- it does not
[-]# matter the type of method. Could be said that only REGISTERs are just
[-]# for servers, the others are either mixed (e.g, OPTIONS) or only for
[-]# end-users.
[-]
[-] if (!search(^"Route:") && !search(^"Record-Route:")) {
[-] lookup("location");
[-] };
but the description was not clear (might be a language translation issue)
as to if this would solve this particular problem, and in testing,
the addition of this code does not seem to change the outcome.
In our lab network, here are the IPaddrs of interest:
192.168.200.20 SIP phone (/24 netblock)
192.168.200.10 Asterisk server (/24 netblock)
192.168.200.30 SER server (re2) (/24 netblock)
10.9.193.135 SER server (re1) (/28 netblock)
10.9.193.148 SER server (re0) (/29 netblock)
10.9.193.130 LCS Signaling port (/28 netblock)
10.9.193.146 LCS Bearer/RTP port (/29 netblock)
and here is the ser.cfg, with just IPaddrs set from the published
sample:
# $Id: gw-pstn.cfg 51 2006-01-31 13:28:04Z /CN=Paul Hazlett/emailAddress=paul at onsip.org $
debug=4
fork=yes
log_stderror=no
listen=192.168.200.30 # INSERT YOUR IP ADDRESS HERE
alias=192.168.200.30
port=5060
children=4
dns=no
rev_dns=no
fifo="/tmp/ser_fifo"
fifo_db_url="mysql://ser:heslo@localhost/ser"
loadmodule "/usr/local/lib/ser/modules/mysql.so"
loadmodule "/usr/local/lib/ser/modules/sl.so"
loadmodule "/usr/local/lib/ser/modules/tm.so"
loadmodule "/usr/local/lib/ser/modules/rr.so"
loadmodule "/usr/local/lib/ser/modules/maxfwd.so"
loadmodule "/usr/local/lib/ser/modules/usrloc.so"
loadmodule "/usr/local/lib/ser/modules/registrar.so"
loadmodule "/usr/local/lib/ser/modules/auth.so"
loadmodule "/usr/local/lib/ser/modules/auth_db.so"
loadmodule "/usr/local/lib/ser/modules/uri.so"
loadmodule "/usr/local/lib/ser/modules/uri_db.so"
loadmodule "/usr/local/lib/ser/modules/domain.so"
loadmodule "/usr/local/lib/ser/modules/mediaproxy.so"
loadmodule "/usr/local/lib/ser/modules/nathelper.so"
loadmodule "/usr/local/lib/ser/modules/textops.so"
loadmodule "/usr/local/lib/ser/modules/avpops.so"
loadmodule "/usr/local/lib/ser/modules/permissions.so"
modparam("auth_db|permissions|uri_db|usrloc",
"db_url", "mysql://ser:heslo@localhost/ser")
modparam("auth_db", "calculate_ha1", 1)
modparam("auth_db", "password_column", "password")
modparam("nathelper", "rtpproxy_disable", 1)
modparam("nathelper", "natping_interval", 0)
modparam("mediaproxy","natping_interval", 30)
modparam("mediaproxy","mediaproxy_socket", "/var/run/mediaproxy.sock")
modparam("mediaproxy","sip_asymmetrics","/usr/local/etc/ser/sip-clients")
modparam("mediaproxy","rtp_asymmetrics","/usr/local/etc/ser/rtp-clients")
modparam("usrloc", "db_mode", 2)
modparam("registrar", "nat_flag", 6)
modparam("rr", "enable_full_lr", 1)
modparam("tm", "fr_inv_timer", 27)
modparam("tm", "fr_inv_timer_avp", "inv_timeout")
modparam("permissions", "db_mode", 1)
modparam("permissions", "trusted_table", "trusted")
route {
# -----------------------------------------------------------------
# Sanity Check Section
# -----------------------------------------------------------------
if (!mf_process_maxfwd_header("10")) {
sl_send_reply("483", "Too Many Hops");
break;
};
if (msg:len > max_len) {
sl_send_reply("513", "Message Overflow");
break;
};
# -----------------------------------------------------------------
# Record Route Section
# -----------------------------------------------------------------
if (method=="INVITE" && client_nat_test("3")) {
# INSERT YOUR IP ADDRESS HERE
record_route_preset("192.168.200.30:5060;nat=yes");
} else if (method!="REGISTER") {
record_route();
};
# -----------------------------------------------------------------
# Call Tear Down Section
# -----------------------------------------------------------------
if (method=="BYE" || method=="CANCEL") {
end_media_session();
};
# -----------------------------------------------------------------
# Loose Route Section
# -----------------------------------------------------------------
if (loose_route()) {
if ((method=="INVITE" || method=="REFER") && !has_totag()) {
sl_send_reply("403", "Forbidden");
break;
};
if (method=="INVITE") {
if (!allow_trusted()) {
if (!proxy_authorize("","subscriber")) {
proxy_challenge("","0");
break;
} else if (!check_from()) {
sl_send_reply("403", "Use From=ID");
break;
};
consume_credentials();
};
if (client_nat_test("3")||search("^Route:.*;nat=yes")){
setflag(6);
use_media_proxy();
};
};
route(1);
break;
};
# -----------------------------------------------------------------
# Call Type Processing Section
# -----------------------------------------------------------------
if (!is_uri_host_local()) {
if (is_from_local() || allow_trusted()) {
route(4);
route(1);
} else {
sl_send_reply("403", "Forbidden");
};
break;
};
if (method=="ACK") {
route(1);
break;
} else if (method=="CANCEL") {
route(1);
break;
} else if (method=="INVITE") {
route(3);
break;
} else if (method=="REGISTER") {
route(2);
break;
};
lookup("aliases");
if (!is_uri_host_local()) {
route(4);
route(1);
break;
};
if (!lookup("location")) {
sl_send_reply("404", "User Not Found");
break;
};
route(1);
}
route[1] {
# -----------------------------------------------------------------
# Default Message Handler
# -----------------------------------------------------------------
#Didn't seem to fix hop count error
# if (!search(^"Route:") && !search(^"Record-Route:")) {
# lookup("location");
# };
t_on_reply("1");
if (!t_relay()) {
if (method=="INVITE" || method=="ACK") {
end_media_session();
};
sl_reply_error();
};
}
route[2] {
# -----------------------------------------------------------------
# REGISTER Message Handler
# -----------------------------------------------------------------
sl_send_reply("100", "Trying");
if (!search("^Contact:[ ]*\*") && client_nat_test("7")) {
setflag(6);
fix_nated_register();
force_rport();
};
if (!www_authorize("","subscriber")) {
www_challenge("","0");
break;
};
if (!check_to()) {
sl_send_reply("401", "Unauthorized");
break;
};
consume_credentials();
if (!save("location")) {
sl_reply_error();
};
}
route[3] {
# -----------------------------------------------------------------
# INVITE Message Handler
# -----------------------------------------------------------------
if (client_nat_test("3")) {
setflag(7);
force_rport();
fix_nated_contact();
};
if (!allow_trusted()) {
if (!proxy_authorize("","subscriber")) {
proxy_challenge("","0");
break;
} else if (!check_from()) {
sl_send_reply("403", "Use From=ID");
break;
};
consume_credentials();
};
if (uri=~"^sip:1[0-9]{10}@") {
strip(1);
};
lookup("aliases");
if (!is_uri_host_local()) {
route(4);
route(1);
break;
};
if (uri=~"^sip:011[0-9]*@") { # International PSTN
route(4);
route(5);
break;
};
if (!lookup("location")) {
if (uri=~"^sip:[0-9]{10}@") { # Domestic PSTN
route(4);
route(5);
break;
};
sl_send_reply("404", "User Not Found");
break;
};
route(4);
route(1);
}
route[4] {
# -----------------------------------------------------------------
# NAT Traversal Section
# -----------------------------------------------------------------
if (isflagset(6) || isflagset(7)) {
if (!isflagset(8)) {
setflag(8);
use_media_proxy();
};
};
}
route[5] {
# -----------------------------------------------------------------
# PSTN Handler
# -----------------------------------------------------------------
rewritehost("10.9.193.130"); # INSERT YOUR PSTN GATEWAY IP ADDRESS
avp_write("i:45", "inv_timeout");
route(1);
}
onreply_route[1] {
if ((isflagset(6) || isflagset(7)) &&
(status=~"(180)|(183)|2[0-9][0-9]")) {
if (!search("^Content-Length:[ ]*0")) {
use_media_proxy();
};
};
if (client_nat_test("1")) {
fix_nated_contact();
};
}
- - - - - - - - - - - - - - - - - - - - - - - - - - -
Any suggestions or ideas as to how to get around this issue are
appreciated!
Frank
More information about the sr-users
mailing list