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

Stefan Sayer wrote: 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