[Serusers] Is SER doc PSTN Gateway example incomplete/incompatible with Asterisk?
Frank Durda IV
frank.durda at hypercube-llc.com
Wed Feb 6 20:49:12 CET 2008
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 at 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 at 192.168.200.30]
Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24982]: DEBUG: to body [<sip:9613789999 at 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 at 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 at 192.168.200.30]
Feb 6 13:20:19 ser1 /usr/local/sbin/ser[24981]: DEBUG: to body [<sip:9613789999 at 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 at 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 at 192.168.200.30]
Feb 6 13:20:48 ser1 /usr/local/sbin/ser[24983]: DEBUG: to body [<sip:9613789999 at 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 at 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 at 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
More information about the sr-users
mailing list