[Serusers] Is SER doc PSTN Gateway example incomplete/incompatible with Asterisk?

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@192.168.200.10>;tag=as0e01f6d8 To: <sip:192.168.200.30> Contact: <sip:asterisk@192.168.200.10> Call-ID: 74f1aaf801a2f3d750d053e82951e1a5(a)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(a)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