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@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@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
Hello,
Frank Durda IV wrote:
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...
isn't that good in your case? it did not spiral 70 times until you notice...
I think the problem lies in this
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
is_uri_host_local() fails because you are using domain module, but have not added the domain 192.168.200.30 to your domain table. try serctl domain [show|add|rm] commands.
Stefan
Stefan Sayer wrote:
Hello,
Frank Durda IV wrote:
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...
isn't that good in your case? it did not spiral 70 times until you notice...
I think the problem lies in this
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
is_uri_host_local() fails because you are using domain module, but have not added the domain 192.168.200.30 to your domain table. try serctl domain [show|add|rm] commands.
Indeed this appears to be one of the problems. In trying different things to get things going, the domain table got deleted and rebuilt a few times and somewhere along the line 192.168.200.30 got left out.
Thanks for the catch!
Now with 192.168.200.30 re-added to the domain table, things get further and a test call claims "Connected" at the SIP phone display for exactly 30 seconds before the SIP phone reports that the Call Ended. Based on the logs it does not appear that SER attempted to contact the PSTN switch, but SER certainly got closer.
An actual INVITE attempt:
Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: SIP Request: Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: method: <OPTIONS> Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: uri: sip:192.168.200.30 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: version: <SIP/2.0> Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: parse_headers: flags=1 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: Found param type 232, <branch> = <z9hG4bK0c3bf79a>; state=6 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: Found param type 235, <rport> = <n/a>; state=17 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: end of header reached, state=5 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: parse_headers: Via found, flags=1 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: parse_headers: this is the first via Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: After parse_msg... Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: preparing to run routing scripts... Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: parse_headers: flags=128 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: end of header reached, state=9 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: DEBUG: get_hdr_field: <To> [22]; uri=[sip:192.168.200.30] Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: DEBUG: to body [sip:192.168.200.30^M ] Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: get_hdr_field: cseq <CSeq>: <102> <OPTIONS> Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: DEBUG:maxfwd:is_maxfwd_present: value = 70 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: DBG:maxfwd:process_maxfwd_header: value 70 decreased to 16 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: DEBUG: add_param: tag=as093ba6ba Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: end of header reached, state=29 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: parse_headers: flags=256 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: DEBUG: get_hdr_body : content_length=0 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: found end of header Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: find_first_route: No Route headers found Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: loose_route: There is no Route HF Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: is_local(): Realm '192.168.200.30' is local Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: lookup(): '' Not found in usrloc Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: is_local(): Realm '192.168.200.30' is local Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: lookup(): '' Not found in usrloc Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: parse_headers: flags=-1 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: check_via_address(192.168.200.10, 192.168.200.10, 0) Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: DEBUG:destroy_avp_list: destroying list 0x0 Feb 6 13:20:02 ser1 /usr/local/sbin/ser[24980]: receive_msg: cleaning up Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: SIP Request: Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: method: <INVITE> Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: uri: sip:9613789999@192.168.200.30 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: version: <SIP/2.0> Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: parse_headers: flags=1 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: Found param type 232, <branch> = <z9hG4bK197936b1>; state=6 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: Found param type 235, <rport> = <n/a>; state=17 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: end of header reached, state=5 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: parse_headers: Via found, flags=1 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: parse_headers: this is the first via Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: After parse_msg... Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: preparing to run routing scripts... Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: parse_headers: flags=128 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: end of header reached, state=9 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG: get_hdr_field: <To> [33]; uri=[sip:9613789999@192.168.200.30] Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG: to body [sip:9613789999@192.168.200.30^M ] Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: get_hdr_field: cseq <CSeq>: <102> <INVITE> Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG:maxfwd:is_maxfwd_present: value = 70 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DBG:maxfwd:process_maxfwd_header: value 70 decreased to 16 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: parse_headers: flags=64 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG: add_param: tag=as5b9f6354 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: end of header reached, state=29 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: parse_headers: flags=256 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG: get_hdr_body : content_length=289 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: found end of header Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: find_first_route: No Route headers found Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: loose_route: There is no Route HF Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: is_local(): Realm '192.168.200.30' is local Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: parse_headers: flags=64 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: parse_headers: flags=64 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: lookup(): '9613789999' Not found in usrloc Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: is_local(): Realm '192.168.200.30' is local Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: lookup(): '9613789999' Not found in usrloc Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: parse_headers: flags=-1 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: is_local(): Realm '192.168.200.30' is local Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: parse_headers: flags=33554432 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: is_local(): Realm '192.168.200.30' is local Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG: t_newtran: msg id=1 , global msg id=0 , T on entrance=0xffffffff Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: parse_headers: flags=-1 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: parse_headers: flags=60 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: t_lookup_request: start searching: hash=17068, isACK=0 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG: RFC3261 transaction matching failed Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG: t_lookup_request: no transaction found Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: SER: new INVITE Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: SIP Request: Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: method: <INVITE> Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: uri: sip:9613789999@192.168.200.30 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: version: <SIP/2.0> Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: parse_headers: flags=1 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: Found param type 232, <branch> = <z9hG4bK197936b1>; state=6 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: Found param type 235, <rport> = <n/a>; state=17 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: end of header reached, state=5 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: parse_headers: Via found, flags=1 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: parse_headers: this is the first via Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: After parse_msg... Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: preparing to run routing scripts... Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: parse_headers: flags=128 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: end of header reached, state=9 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: DEBUG: get_hdr_field: <To> [33]; uri=[sip:9613789999@192.168.200.30] Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: DEBUG: to body [sip:9613789999@192.168.200.30^M ] Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: get_hdr_field: cseq <CSeq>: <102> <INVITE> Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: DEBUG:maxfwd:is_maxfwd_present: value = 70 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: DBG:maxfwd:process_maxfwd_header: value 70 decreased to 16 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: parse_headers: flags=64 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: DEBUG: add_param: tag=as5b9f6354 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: end of header reached, state=29 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: parse_headers: flags=256 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: DEBUG: get_hdr_body : content_length=289 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: parse_headers: flags=-1 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: found end of header Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: find_first_route: No Route headers found Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: check_via_address(192.168.200.10, 192.168.200.10, 0) Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: WARNING:vqm_resize: resize(0) called Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG: reply sent out. buf=0x8119e08: SIP/2.0 1..., shmem=0x284ec940: SIP/2 .0 1 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: loose_route: There is no Route HF Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG: _reply_light: finished Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG: mk_proxy: doing DNS lookup... Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: check_via_address(192.168.200.10, 192.168.200.10, 0) Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: is_local(): Realm '192.168.200.30' is local Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: parse_headers: flags=64 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: parse_headers: flags=64 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: lookup(): '9613789999' Not found in usrloc Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG: add_to_tail_of_timer[0]: 0x284eb540 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: SER: new transaction fwd'ed Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: is_local(): Realm '192.168.200.30' is local Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG:destroy_avp_list: destroying list 0x0 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: receive_msg: cleaning up Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: lookup(): '9613789999' Not found in usrloc Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: parse_headers: flags=-1 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: is_local(): Realm '192.168.200.30' is local Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: parse_headers: flags=33554432 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: is_local(): Realm '192.168.200.30' is local Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: DEBUG: t_newtran: msg id=1 , global msg id=0 , T on entrance=0xffffffff Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: parse_headers: flags=-1 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: parse_headers: flags=60 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: t_lookup_request: start searching: hash=17068, isACK=0 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: DEBUG: RFC3261 transaction matched, tid=197936b1 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: DEBUG: t_lookup_request: transaction found (T=0x284eb418) Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: DEBUG: reply retransmitted. buf=0x282d7420: SIP/2.0 1..., shmem=0x284ec940: SIP/2.0 1 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: DEBUG:destroy_avp_list: destroying list 0x284ed028 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: receive_msg: cleaning up Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24984]: DEBUG: timer routine:4,tl=0x284eb530 next=0x0 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : request resending (t=0x284eb418, INVITE si ... ) Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24984]: DEBUG: add_to_tail_of_timer[5]: 0x284eb530 Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : done Feb 6 13:20:21 ser1 /usr/local/sbin/ser[24984]: DEBUG: timer routine:5,tl=0x284eb530 next=0x0 Feb 6 13:20:21 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : request resending (t=0x284eb418, INVITE si ... ) Feb 6 13:20:21 ser1 /usr/local/sbin/ser[24984]: DEBUG: add_to_tail_of_timer[6]: 0x284eb530 Feb 6 13:20:21 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : done Feb 6 13:20:25 ser1 /usr/local/sbin/ser[24984]: DEBUG: timer routine:6,tl=0x284eb530 next=0x0 Feb 6 13:20:25 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : request resending (t=0x284eb418, INVITE si ... ) Feb 6 13:20:25 ser1 /usr/local/sbin/ser[24984]: DEBUG: add_to_tail_of_timer[7]: 0x284eb530 Feb 6 13:20:25 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : done Feb 6 13:20:29 ser1 /usr/local/sbin/ser[24984]: DEBUG: timer routine:7,tl=0x284eb530 next=0x0 Feb 6 13:20:29 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : request resending (t=0x284eb418, INVITE si ... ) Feb 6 13:20:29 ser1 /usr/local/sbin/ser[24984]: DEBUG: add_to_tail_of_timer[7]: 0x284eb530 Feb 6 13:20:29 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : done Feb 6 13:20:33 ser1 /usr/local/sbin/ser[24984]: DEBUG: timer routine:7,tl=0x284eb530 next=0x0 Feb 6 13:20:33 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : request resending (t=0x284eb418, INVITE si ... ) Feb 6 13:20:33 ser1 /usr/local/sbin/ser[24984]: DEBUG: add_to_tail_of_timer[7]: 0x284eb530 Feb 6 13:20:33 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : done Feb 6 13:20:37 ser1 /usr/local/sbin/ser[24984]: DEBUG: timer routine:7,tl=0x284eb530 next=0x0 Feb 6 13:20:37 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : request resending (t=0x284eb418, INVITE si ... ) Feb 6 13:20:37 ser1 /usr/local/sbin/ser[24984]: DEBUG: add_to_tail_of_timer[7]: 0x284eb530 Feb 6 13:20:37 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : done Feb 6 13:20:41 ser1 /usr/local/sbin/ser[24984]: DEBUG: timer routine:7,tl=0x284eb530 next=0x0 Feb 6 13:20:41 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : request resending (t=0x284eb418, INVITE si ... ) Feb 6 13:20:41 ser1 /usr/local/sbin/ser[24984]: DEBUG: add_to_tail_of_timer[7]: 0x284eb530 Feb 6 13:20:41 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : done Feb 6 13:20:45 ser1 /usr/local/sbin/ser[24984]: DEBUG: timer routine:7,tl=0x284eb530 next=0x0 Feb 6 13:20:45 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : request resending (t=0x284eb418, INVITE si ... ) Feb 6 13:20:45 ser1 /usr/local/sbin/ser[24984]: DEBUG: add_to_tail_of_timer[7]: 0x284eb530 Feb 6 13:20:45 ser1 /usr/local/sbin/ser[24984]: DEBUG: retransmission_handler : done Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24984]: DEBUG: timer routine:0,tl=0x284eb540 next=0x0 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24984]: DEBUG: final_response_handler:stop retr. and send CANCEL (0x284eb418) Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24984]: ->>>>>>>>> T_code=100, new_code=408 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24984]: DEBUG: relay_reply: branch=0, save=0, relay=0 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24984]: parse_headers: flags=-1 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24984]: check_via_address(192.168.200.10, 192.168.200.10, 0) Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24984]: DEBUG: add_to_tail_of_timer[4]: 0x284eb4c4 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24984]: DEBUG: add_to_tail_of_timer[0]: 0x284eb4d4 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24984]: DEBUG: reply relayed. buf=0x8119338: SIP/2.0 4..., shmem=0x284ec940: SIP/2. 0 4 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24984]: DEBUG: final_response_handler : done Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24984]: DEBUG: timer routine:7,tl=0x284eb530 next=0x0 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: SIP Request: Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: method: <ACK> Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: uri: sip:9613789999@192.168.200.30 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: version: <SIP/2.0> Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: parse_headers: flags=1 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: Found param type 232, <branch> = <z9hG4bK197936b1>; state=6 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: Found param type 235, <rport> = <n/a>; state=17 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: end of header reached, state=5 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: parse_headers: Via found, flags=1 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: parse_headers: this is the first via Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: After parse_msg... Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: preparing to run routing scripts... Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: DEBUG : sl_filter_ACK: to late to be a local ACK! Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: parse_headers: flags=128 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: DEBUG: add_param: tag=885e88d7a6aa5adea22f18babafe19d9-0123 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: end of header reached, state=29 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: DEBUG: get_hdr_field: <To> [75]; uri=[sip:9613789999@192.168.200.30] Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: DEBUG: to body [sip:9613789999@192.168.200.30] Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: get_hdr_field: cseq <CSeq>: <102> <ACK> Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: DEBUG:maxfwd:is_maxfwd_present: value = 70 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: DBG:maxfwd:process_maxfwd_header: value 70 decreased to 16 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: DEBUG: add_param: tag=as5b9f6354 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: end of header reached, state=29 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: SIP Request: Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: method: <BYE> Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: parse_headers: flags=256 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: uri: sip:9613789999@192.168.200.30 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: version: <SIP/2.0> Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: parse_headers: flags=1 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: DEBUG: get_hdr_body : content_length=0 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: Found param type 232, <branch> = <z9hG4bK6971a2eb>; state=6 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: Found param type 235, <rport> = <n/a>; state=17 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: end of header reached, state=5 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: parse_headers: Via found, flags=1 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: found end of header Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: parse_headers: this is the first via Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: After parse_msg... Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: preparing to run routing scripts... Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: find_first_route: No Route headers found Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: loose_route: There is no Route HF Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: parse_headers: flags=128 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: DEBUG: add_param: tag=885e88d7a6aa5adea22f18babafe19d9-0123 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: end of header reached, state=29 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: DEBUG: to body [sip:9613789999@192.168.200.30] Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: DEBUG:maxfwd:is_maxfwd_present: value = 70 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: DBG:maxfwd:process_maxfwd_header: value 70 decreased to 16 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: DEBUG: add_param: tag=as5b9f6354 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: end of header reached, state=29 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: parse_headers: flags=-1 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: parse_headers: flags=60 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: t_lookup_request: start searching: hash=17068, isACK=1 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: DEBUG: RFC3261 transaction matched, tid=197936b1 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: DEBUG: t_lookup_request: transaction found (T=0x284eb418) Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: DEBUG: get_hdr_body : content_length=0 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: DEBUG:destroy_avp_list: destroying list 0x0 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: receive_msg: cleaning up Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: found end of header Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: find_first_route: No Route headers found Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: loose_route: There is no Route HF Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: is_local(): Realm '192.168.200.30' is local Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: lookup(): '9613789999' Not found in usrloc Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: is_local(): Realm '192.168.200.30' is local Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: lookup(): '9613789999' Not found in usrloc Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: parse_headers: flags=-1 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: check_via_address(192.168.200.10, 192.168.200.10, 0) Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: DEBUG:destroy_avp_list: destroying list 0x0 Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24980]: receive_msg: cleaning up Feb 6 13:20:49 ser1 /usr/local/sbin/ser[24984]: DEBUG: timer routine:0,tl=0x284eb4d4 next=0x0 Feb 6 13:20:49 ser1 /usr/local/sbin/ser[24984]: DEBUG: timer routine:4,tl=0x284eb4c4 next=0x0 Feb 6 13:20:53 ser1 /usr/local/sbin/ser[24984]: DEBUG: timer routine:2,tl=0x284eb460 next=0x0 Feb 6 13:20:53 ser1 /usr/local/sbin/ser[24984]: DEBUG: wait_handler : removing 0x284eb418 from table Feb 6 13:20:53 ser1 /usr/local/sbin/ser[24984]: DEBUG: delete transaction 0x284eb418 Feb 6 13:20:53 ser1 /usr/local/sbin/ser[24984]: DEBUG: wait_handler : done
Now according to a log() call stuck at the beginning of route[5], it did get called twice during all this, but I see no indication that the re-write of the IP address actually occurred, and don't have any evidence that the switch at that IP address was ever contacted.
Suggestions/Comments appreciated!
Frank
Hello,
Frank Durda IV wrote:
Thanks for the catch!
Now with 192.168.200.30 re-added to the domain table, things get further and a test call claims "Connected" at the SIP phone display for exactly 30 seconds before the SIP phone reports that the Call Ended. Based on the logs it does not appear that SER attempted to contact the PSTN switch, but SER certainly got closer.
to me it looks like the INVITE is sent out and retried. an ngrep would definitely be more revealing about what happens here (ngrep port 5060 -W byline -d any).
Stefan
I think this has to do with ACK handling. One can probably argue that this is a bug in the config, but due to a complete config change in 2.0, it was never fixed. If I recall correctly, there is a missing relaying of acks without route headers. I'm on mobile, so I cannot check. g-)
------- Original message ------- From: Stefan Sayer stefan.sayer@iptego.com Cc: serusers@lists.iptel.org Sent: 6.2.'08, 20:59
Hello,
Frank Durda IV wrote:
Thanks for the catch!
Now with 192.168.200.30 re-added to the domain table, things get further and a test call claims "Connected" at the SIP phone display for exactly 30 seconds before the SIP phone reports that the Call Ended. Based on the logs it does not appear that SER attempted to contact the PSTN switch, but SER certainly got closer.
to me it looks like the INVITE is sent out and retried. an ngrep would definitely be more revealing about what happens here (ngrep port 5060 -W byline -d any).
Stefan
-- Stefan Sayer VoIP Services
stefan.sayer@iptego.com www.iptego.com
iptego GmbH Am Borsigturm 40 13507 Berlin Germany
Amtsgericht Charlottenburg, HRB 101010 Geschaeftsfuehrer: Alexander Hoffmann _______________________________________________ Serusers mailing list Serusers@lists.iptel.org http://lists.iptel.org/mailman/listinfo/serusers
Stefan Sayer wrote:
to me it looks like the INVITE is sent out and retried. an ngrep would definitely be more revealing about what happens here (ngrep port 5060 -W byline -d any).
Okay, I can see the problem here. The INVITE is being sent to the PSTN switch, but with an unreachable return IP address. That is, SER isn't using the return IP address for the network interface that the packet is being sent out on, and so the PSTN switch has no way to send a reply that will go anywhere useful, assuming it pays attention to the sender address on the UDP packet itself:
ngrep -W byline -d re1 port 5060 interface: re1 (10.9.193.128/255.255.255.240) filter: (ip or ip6) and ( port 5060 ) # U 192.168.200.30:5060 -> 10.9.193.130:5060 INVITE sip:9613789999@10.9.193.130 SIP/2.0. Record-Route: sip:9613789999@192.168.200.30:5060;nat=yes;ftag=as0bb39a60;lr=on. Via: SIP/2.0/UDP 192.168.200.30;branch=z9hG4bK1f28.759505c2.0. Via: SIP/2.0/UDP 192.168.200.10:5060;branch=z9hG4bK51253e7b;rport=5060. From: "VOIP TEST 1000" sip:3797271700@192.168.200.30;tag=as0bb39a60. To: sip:9613789999@192.168.200.30. Contact: sip:3797271700@192.168.200.10:5060. Call-ID: 5fece4d70f005f4b3180713e0227258b@192.168.200.30. CSeq: 102 INVITE. User-Agent: Asterisk PBX. Max-Forwards: 16. Date: Wed, 06 Feb 2008 14:46:28 GMT. Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY. Supported: replaces. Content-Type: application/sdp. Content-Length: 289. . v=0. o=root 1245 1245 IN IP4 192.168.200.10. s=session. c=IN IP4 192.168.200.10. t=0 0. m=audio 15290 RTP/AVP 0 3 8 101. a=rtpmap:0 PCMU/8000. a=rtpmap:3 GSM/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-16. a=silenceSupp:off - - - -. a=ptime:20. a=sendrecv.
As mentioned earlier, the re1 interface IP address on the SER box is 10.9.193.135, so this should be the address presented to the PSTN switch for SIP replies, not the 192.168.200.30, which is on an unreachable network.
In our setup there will be three interfaces involved, one dealing with SIP only and one dealing with RTP only (from the PSTN switch), and one from other places like the Asterisk box with both SIP and RTP packets. So SER needs to deal with being visible from multiple interfaces and replying in reachable ways from all.
Arguably, the references to 192.168.200.30 in the invite itself are also wrong, as that address is not reachable from the PSTN switch, only the 10.9.193.135 address would be reachable.
So, what's the best way to get SER to do the right thing? In our config, SER is obviously forcing this behavior (possibly a result of missing or excess listen or alias settings?), because a typical program would not encounter this issue, as telnet/ping run from the SER box go to the right place and see replies:
ser1# telnet 10.9.193.130 Trying 10.9.193.130... Connected to 10.9.193.130. Escape character is '^]'.
This is LABXTXBR549 SP-B Username: ...
Frank
Hello,
Frank Durda IV wrote:
Okay, I can see the problem here. The INVITE is being sent to the PSTN switch, but with an unreachable return IP address. That is, SER isn't using the return IP address for the network interface that the packet is being sent out on, and so the PSTN switch has no way to send a reply that will go anywhere useful, assuming it pays attention to the sender address on the UDP packet itself:
...
Arguably, the references to 192.168.200.30 in the invite itself are also wrong, as that address is not reachable from the PSTN switch, only the 10.9.193.135 address would be reachable.
SER will by default send the packet from the socket it received the request on. So try using the right IP (10.9.193.135 in that case) at the asterisk box, or
So, what's the best way to get SER to do the right thing?
you can also use force_send_socket (force_send_socket([proto:]address[:port]) to set the outgoing socket. In your setup with one 'public' interface and asterisk sending to the other one you will actually need it.
Regards Stefan (who is not really talking about things he does know here)
In our config, SER is obviously forcing this behavior (possibly a result of missing or excess listen or alias settings?), because a typical program would not encounter this issue, as telnet/ping run from the SER box go to the right place and see replies: ser1# telnet 10.9.193.130 Trying 10.9.193.130... Connected to 10.9.193.130. Escape character is '^]'.
This is LABXTXBR549 SP-B Username: ...
Frank
Stefan Sayer wrote:
SER will by default send the packet from the socket it received the request on. So try using the right IP (10.9.193.135 in that case) at the asterisk box, or
you can also use force_send_socket (force_send_socket([proto:]address[:port]) to set the outgoing socket. In your setup with one 'public' interface and asterisk sending to the other one you will actually need it.
I guess I didn't describe our setup well enough. Here it is drawn a different way. Here is network "A" /24
[SIP phone 192.168.200.20]-----+ [Asterisk box 192.168.200.10]--+----[SER interface re2 192.168.200.30] (Three devices on this network, plus the switch)
and Network "B" /28
[SER interface re1 10.9.193.135]-----[LCS Switch SIP interface 10.9.193.130] (two devices on this network, plus a switch)
and Network "C" /29
[SER interface re0 10.9.193.148]-----[LCS Switch Bearer interface 10.9.193.146] (two devices on this network, plus a router)
These are the basic connections and isolated networks, Each network can't see the other (intentional). Only a device connected to two or more of the networks can see into those directly connected networks.
So, here is a test call as it comes in from the Asterisk box on re2:
ser1# ngrep -W byline -d re2 port 5060 interface: re2 (192.168.200.0/255.255.255.0) filter: (ip or ip6) and ( port 5060 )
# U 192.168.200.10:5060 -> 192.168.200.30:5060 INVITE sip:9613789999@192.168.200.30 SIP/2.0. Via: SIP/2.0/UDP 192.168.200.10:5060;branch=z9hG4bK72e3cd8d;rport. From: "VOIP TEST 1000" sip:3797271700@192.168.200.30;tag=as0e33db9b. To: sip:9613789999@192.168.200.30. Contact: sip:3797271700@192.168.200.10. Call-ID: 45b82ab572cfaddd18afc02a5cd4275c@192.168.200.30. CSeq: 102 INVITE. User-Agent: Asterisk PBX. Max-Forwards: 70. Date: Wed, 06 Feb 2008 16:10:40 GMT. Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY. Supported: replaces. Content-Type: application/sdp. Content-Length: 289. . v=0. o=root 1245 1245 IN IP4 192.168.200.10. s=session. c=IN IP4 192.168.200.10. t=0 0. m=audio 10424 RTP/AVP 0 3 8 101. a=rtpmap:0 PCMU/8000. a=rtpmap:3 GSM/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-16. a=silenceSupp:off - - - -. a=ptime:20. a=sendrecv.
# U 192.168.200.30:5060 -> 192.168.200.10:5060 SIP/2.0 100 trying -- your call is important to us. Via: SIP/2.0/UDP 192.168.200.10:5060;branch=z9hG4bK72e3cd8d;rport=5060. From: "VOIP TEST 1000" sip:3797271700@192.168.200.30;tag=as0e33db9b. To: sip:9613789999@192.168.200.30. Call-ID: 45b82ab572cfaddd18afc02a5cd4275c@192.168.200.30. CSeq: 102 INVITE. Server: Sip EXpress router (0.9.6 (i386/freebsd)). Content-Length: 0. Warning: 392 192.168.200.30:5060 "Noisy feedback tells: pid=29750 req_src_ip=19 2.168.200.10 req_src_port=5060 in_uri=sip:9613789999@192.168.200.30 out_uri=sip: 9613789999@10.9.193.130 via_cnt==1". .
time passes...
# U 192.168.200.30:5060 -> 192.168.200.10:5060 SIP/2.0 408 Request Timeout. Via: SIP/2.0/UDP 192.168.200.10:5060;branch=z9hG4bK72e3cd8d;rport=5060. From: "VOIP TEST 1000" sip:3797271700@192.168.200.30;tag=as0e33db9b. To: sip:9613789999@192.168.200.30;tag=4ba1e3c69d2fb2c7ac6c1995ba01e0a8-e559. Call-ID: 45b82ab572cfaddd18afc02a5cd4275c@192.168.200.30. CSeq: 102 INVITE. Server: Sip EXpress router (0.9.6 (i386/freebsd)). Content-Length: 0. Warning: 392 192.168.200.30:5060 "Noisy feedback tells: pid=29760 req_src_ip=19 2.168.200.10 req_src_port=5060 in_uri=sip:9613789999@192.168.200.30 out_uri=sip: 9613789999@10.9.193.130 via_cnt==0". . # U 192.168.200.10:5060 -> 192.168.200.30:5060 ACK sip:9613789999@192.168.200.30 SIP/2.0. Via: SIP/2.0/UDP 192.168.200.10:5060;branch=z9hG4bK72e3cd8d;rport. From: "VOIP TEST 1000" sip:3797271700@192.168.200.30;tag=as0e33db9b. To: sip:9613789999@192.168.200.30;tag=4ba1e3c69d2fb2c7ac6c1995ba01e0a8-e559. Contact: sip:3797271700@192.168.200.10. Call-ID: 45b82ab572cfaddd18afc02a5cd4275c@192.168.200.30. CSeq: 102 ACK. User-Agent: Asterisk PBX. Max-Forwards: 70. Content-Length: 0. .
# U 192.168.200.10:5060 -> 192.168.200.30:5060 BYE sip:9613789999@192.168.200.30 SIP/2.0. Via: SIP/2.0/UDP 192.168.200.10:5060;branch=z9hG4bK1f3f55f0;rport. From: "VOIP TEST 1000" sip:3797271700@192.168.200.30;tag=as0e33db9b. To: sip:9613789999@192.168.200.30;tag=4ba1e3c69d2fb2c7ac6c1995ba01e0a8-e559. Call-ID: 45b82ab572cfaddd18afc02a5cd4275c@192.168.200.30. CSeq: 103 BYE. User-Agent: Asterisk PBX. Max-Forwards: 70. Content-Length: 0. .
# U 192.168.200.30:5060 -> 192.168.200.10:5060 SIP/2.0 404 User Not Found. Via: SIP/2.0/UDP 192.168.200.10:5060;branch=z9hG4bK1f3f55f0;rport=5060. From: "VOIP TEST 1000" sip:3797271700@192.168.200.30;tag=as0e33db9b. To: sip:9613789999@192.168.200.30;tag=4ba1e3c69d2fb2c7ac6c1995ba01e0a8-e559. Call-ID: 45b82ab572cfaddd18afc02a5cd4275c@192.168.200.30. CSeq: 103 BYE. Server: Sip EXpress router (0.9.6 (i386/freebsd)). Content-Length: 0. Warning: 392 192.168.200.30:5060 "Noisy feedback tells: pid=29748 req_src_ip=19 2.168.200.10 req_src_port=5060 in_uri=sip:9613789999@192.168.200.30 out_uri=sip: 9613789999@192.168.200.30 via_cnt==1". .
So just about everything looks sane here apart from these three things:
1. Call failed to go anywhere (more on that in a moment)
2. This 404 User Not Found reply to the BYE. What's this?
3. The "Noisy feedback tells" warning. Bad or just annoying?
Meanwhile, during all of that activity on interface re2 (between Asterisk and SER system), we see this on interface re1 (between SER and PSTN gateway):
ser1# ngrep -W byline -d re1 port 5060 interface: re1 (10.9.193.128/255.255.255.240) NOTE CORRECT NETBLOCK & SIZE) filter: (ip or ip6) and ( port 5060 ) # U 192.168.200.30:5060 -> 10.9.193.130:5060 NOTE INCORRECT SENDER FOR THIS NETBLOCK INVITE sip:9613789999@10.9.193.130 SIP/2.0. Record-Route: sip:9613789999@192.168.200.30:5060;nat=yes;ftag=as0e33db9b;lr=on. Via: SIP/2.0/UDP 192.168.200.30;branch=z9hG4bK836b.f113c606.0. Via: SIP/2.0/UDP 192.168.200.10:5060;branch=z9hG4bK72e3cd8d;rport=5060. From: "VOIP TEST 1000" sip:3797271700@192.168.200.30;tag=as0e33db9b. To: sip:9613789999@192.168.200.30. Contact: sip:3797271700@192.168.200.10:5060. Call-ID: 45b82ab572cfaddd18afc02a5cd4275c@192.168.200.30. CSeq: 102 INVITE. User-Agent: Asterisk PBX. Max-Forwards: 16. Date: Wed, 06 Feb 2008 16:10:40 GMT. Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY. Supported: replaces. Content-Type: application/sdp. Content-Length: 289. . v=0. o=root 1245 1245 IN IP4 192.168.200.10. s=session. c=IN IP4 192.168.200.10. t=0 0. m=audio 10424 RTP/AVP 0 3 8 101. a=rtpmap:0 PCMU/8000. a=rtpmap:3 GSM/8000. a=rtpmap:8 PCMA/8000. a=rtpmap:101 telephone-event/8000. a=fmtp:101 0-16. a=silenceSupp:off - - - -. a=ptime:20. a=sendrecv.
repeated a number of times, but no reply is seen because the return address of the SER system on the packets and in the payload is that of the re2 interface, not the re1 interface that this packet was emitted on. The PSTN gateway device therefore can't get a reply back to the SER system. The SER system should have given 10.9.193.135 as the reply address on this interface, not 192.168.200.30. Clearly the OS knows the correct interface to send the packet out on, but SER may not be aware that this is happening.
Note that the above test was done with no listen and no alias entries in the ser.cfg file, and the result appears unchanged from when values were specified (see previous mails).
So, this is a case of message sent out of the SER on thr re1 interface towards the PSTN switch, and not a reply packet in response to the INVITE originally received on the re2 interface.
It still looks like SER for some reason is forcing the return address to be the first interface address it comes across when it starts, rather than using a reply address appropriate for the interface and network that the packet is leaving the SER server on.
Now, as to using force_send_socket(), how exactly does this work? I have not located any documentation other than "added to code" comments in the .c files, so its impact is not clear.
For example, does force_send_socket() affect just the next packet being transmitted, or does it get used for all packets sent from this point forward, until another force_send_socket() call is made? If it just applies to one packet, should it force_send_socket() be invoked in route[5], after the rewritehost() and avp_write, but before route(1)?
As we only want to fix the packets headed out the re1 interface (to the PSTN switch) to have a reachable return address for that network, and not disturb the packets transmitted out the re2 interface (back towards the asterisk box), we need to know how long the effects of a force_send_socket() last.
So if force_send_socket applies to ALL subsequent socket writes, this means we must save and restore the original values following its use on packets going out the re1 interface. I see there is a get_send_socket that might accomplish this. What's the best way to hold on to something like this for later use in a force_send_socket() call? Assuming it is a persistent setting, where would be the appropriate place to save, set and then restore to force the desired behavior?
This actually feels somewhat klunky, and I suspect that this may not be the appropriate solution as someone must be using a SER box with more than network interface and deal with this very situation. There are lots of daemons listening on UNIX servers with multiple interfaces that have to do nothing special at all to get outgoing packets to contain the right Sender addresses. including DNS servers that are making queries that are also using UDP.
In our case, the PSTN switch is a tad dim in the routing department on the signaling interface, and signaling destinations it talks to need to be in the same netblock as the signaling interfaces on that switch. (The limitations on the bearer side are even more primitive, with all packets sent to a specific single MAC address (determined when that interface first became active) regardless of the actual destination address on the packet that the switch emits. Ick.)
I think I have enough hardware in front of the bearer interfaces on that switch to hide its simple view of the world, but the SIP signaling side would really like packets it receives from the SER system to be correctly addressed.
Thanks for the ideas and any more you have,
Frank
Hello again,
I think I understand well your network setup now ;)
Frank Durda IV wrote: ...
It still looks like SER for some reason is forcing the return address to be the first interface address it comes across when it starts, rather than using a reply address appropriate
no, by default it re-uses the socket that it received the request on, if you don't tell it force_send_socket.
for the interface and network that the packet is leaving the SER server on.
Now, as to using force_send_socket(), how exactly does this work? I have not located any documentation other than "added to code" comments in the .c files, so its impact is not clear.
it just forces the send socket for that requests' forwarding. So just do force_send_socket("10.9.193.135"); before you do rewritehost() in route[5], i.e.
force_send_socket("10.9.193.135"); rewritehost("10.9.193.130"); # INSERT YOUR PSTN GATEWAY IP ADDRESS ...
if the route processing is ended and the message is sent out, the game begins again with the next message.
you can also try to set mhomed=yes (general config option), then it will detect on which interface to send out the message.
For example, does force_send_socket() affect just the next packet being transmitted, or does it get used for all packets sent from
yes, only the ones you are sending while processing this message.
this point forward, until another force_send_socket() call is made? If it just applies to one packet, should it force_send_socket() be invoked in route[5], after the rewritehost() and avp_write, but before route(1)?
I think it does not really matter whether force_send_socket is called before or after rewritehost and avp_write. What the function does is to save the socket to send the message when it is sent out.
Stefan
Stefan Sayer wrote:
Hello again,
I think I understand well your network setup now ;)
mhomed=yes (general config option), then it will detect on which interface to send out the message.
mhomed=yes was the final missing bit, and now packets emitted from any interface from SER have a reasonable sender IP address in the packet and payload. This got a call from the SIP phone to the PSTN switch and got a call established (no audio), so 80 points there.
It is an interesting question as to why that isn't the default or at least included in the samples, as it should be harmless on a system with only one interface but would avoid confusion if a system had two or more interfaces, even if one was purely for managament and the other for all SIP/VOIP related communications.
Now we shall puzzle as to why mediaproxy doesn't seem to have done anything, with the SIP phone and PSTN gateway still trying to send RTP packets direct to one another, something that doesn't work as the two networks don't meet. We will go off and ponder why the proxy addresses didn't get patched into the SIP messages.
Thanks again to all who responded!
Frank
Hello,
Frank Durda IV wrote:
Stefan Sayer wrote:
Hello again,
I think I understand well your network setup now ;)
mhomed=yes (general config option), then it will detect on which interface to send out the message.
mhomed=yes was the final missing bit, and now packets emitted from any interface from SER have a reasonable sender IP address in the packet and payload. This got a call from the SIP phone to the PSTN switch and got a call established (no audio), so 80 points there.
It is an interesting question as to why that isn't the default or at least included in the samples, as it should be harmless on a system with only one interface but would avoid confusion if a system had two or more interfaces, even if one was purely for managament and the other for all SIP/VOIP related communications.
I guess it is a performance issue - there is a little performance penalty introduced, as it needs to open a socket for every outgoing message just to see which socket to use. If you look at ser-oob.cfg mhomed=yes is there (but greyed out).
Now we shall puzzle as to why mediaproxy doesn't seem to have done anything, with the SIP phone and PSTN gateway still trying to send RTP packets direct to one another, something that doesn't work as the two networks don't meet. We will go off and ponder why the proxy addresses didn't get patched into the SIP messages.
good luck!
Stefan
Thanks again to all who responded!
Frank
-
Frank Durda IV -
Greger Viken Teigre -
Stefan Sayer