Hello,
I am using OpenSER v1.0.
I have a problem with the following SIP scenario with openser:
- A-Party invites B-Party to a call session. While B-Party is 180 'Ringing', A-Party CANCELs the call session that it first initiated
ACK messages for the 487 'Request Terminated' seems to fail to close the corresponding transaction as 487 continue to be sent multiple times until timeout.
The message trace shown below is part of the message trace produced for the above scenario displaying message frames in sequence F89 to F137. OpenSER is running on all proxies.
Initially everything works as expected: INVITEs, 100 'Trying's and 180 'Ringing' messages are routed correctly from A to B and from B to A via the intermediate proxies (this is not shown below). While still 'Ringing', A-Party CANCEL's the call (sends a CANCEL message) message: F107 in trace below. This also initally routes OK.
But I expect the call flow for this scenario to stop at message: F130 once the 487 'Request Terminated' has routed its way back from the B-Party to the A-Party and a final 'ACK' is sent by the A-Party to the previous proxy: Proxy-1.
But what actually occurs is that OpenSER running on Proxy-1 automatically resends a 487 'Request Terminated' at message F131 identical to the '487' it first sent at message F121. This in turn prompts further ACKs and 487s until it finally times out at message F186 (not shown below).
I have also included part of the OpenSER message trace set at log level 9 which corresponds to ACK messages F130 and F132 received at proxy-A which do not appear to close the transaction of the preceding 487 'Request Terminated' messages - identical 487 'Request Terminate' messages are later resent from Proxy-1.
Can you help me to:
- identify and resolve the problem of multiple resends of 487 'Request Terminated' messages by Proxy-1.
Best regards,
Andrew Augustin
-------
A-Party Proxy-1 Proxy-2 Proxy-3 B-Party
10.1.195.134 10.1.195.134 127.0.0.1:50 127.0.0.1:50 10.1.195.208
|>F89 INVITE>| | | |
|<us 100 F90<| | | |
| |>F91 INVITE (sdp)------->| |
| |<important to us 100 F92<| |
| | |<INVITE F93<| |
| | |>F94 100 tr>| |
| | |>F95 INVITE>| |
| | |<us 100 F96<| |
| |<-------(sdp) INVITE F97<| |
| |>F98 100 trying -- your >| |
| |>F99 INVITE (sdp)-------------------->|
| |<-------------------- Trying 100 F100<|
| |<------------------- Ringing 180 F101<|
| |>F102 180 Ringing ------>| |
| | |<g 180 F103<| |
| | |>F104 180 R>| |
| |<------ Ringing 180 F105<| |
|<g 180 F106<| | | |
|<g 180 F106<| | | |
|>F107 CANCE>| | | |
| |>F108 CANCEL ----------->| |
|<g 200 F109<| | | |
| | |<ANCEL F110<| |
| |<---- canceling 200 F111<| |
| | |>F112 CANCE>| |
| | |>F113 200 c>| |
| |<----------- CANCEL F114<| |
| | |<g 200 F115<| |
| |>F116 CANCEL ------------------------>|
| |>F117 200 canceling ---->| |
| |<-------- Request Terminated 487 F118<|
| |<------------------------ OK 200 F119<|
| |>F120 ACK --------------------------->|
| |>F121 487 Request Termin>| |
| |<-------------- ACK F122<| |
| | |<d 487 F123<| |
| | |>F124 ACK ->| |
| | |>F125 487 R>| |
| | |<- ACK F126<| |
| |<est Terminated 487 F127<| |
| |>F128 ACK -------------->| |
|<d 487 F129<| | | |
|>F130 ACK ->| | | |
| |>F131 487 Request Termin>| |
| |<-------------- ACK F132<| |
|<d 487 F133<| | | |
|>F134 ACK ->| | | |
| |>F135 487 Request Termin>| |
|<d 487 F136<| | | |
| |<-------------- ACK F137<| |
Part of OpenSER log file log-level 9 corresponding to ACK messages F130 and F132 from above trace:-
3(12429) DEBUG: add_to_tail_of_timer[4]: 0xb60e0090
3(12429) DEBUG: add_to_tail_of_timer[0]: 0xb60e00a0
3(12429) DEBUG:tm:relay_reply: sent buf=0x828b9c0: SIP/2.0 4..., shmem=0xb60e1530: SIP/2.0 4
3(12429) DEBUG: cleanup_uac_timers: RETR/FR timers reset
3(12429) DEBUG:destroy_avp_list: destroying list (nil)
3(12429) receive_msg: cleaning up
4(12430) SIP Request:
4(12430) method: <ACK>
4(12430) uri: <sip:testuser_b@generaltests.genericdomain>
4(12430) version: <SIP/2.0>
4(12430) parse_headers: flags=2
4(12430) Found param type 232, <branch> = <z9hG4bK1BCF7778>; state=16
4(12430) end of header reached, state=5
4(12430) parse_headers: Via found, flags=2
4(12430) parse_headers: this is the first via
4(12430) After parse_msg...
4(12430) preparing to run routing scripts...
4(12430) DEBUG : sl_filter_ACK: to late to be a local ACK!
4(12430) parse_headers: flags=100
4(12430) get_hdr_field: cseq <CSeq>: <640> <ACK>
4(12430) DEBUG: add_param: tag=1F5CE0A1
4(12430) DEBUG:parse_to:end of header reached, state=29
4(12430) DEBUG: get_hdr_field: <To> [83]; uri=[sip:testuser_b@generaltests.genericdomain]
4(12430) DEBUG: to body ["testuser_b" <sip:testuser_b@generaltests.genericdomain>]
4(12430) DEBUG: get_hdr_body : content_length=0
4(12430) found end of header
4(12430) DEBUG: is_maxfwd_present: max_forwards header not found!
4(12430) DEBUG: add_param: tag=1AE725BF
4(12430) DEBUG:parse_to:end of header reached, state=29
4(12430) parse_headers: flags=200
4(12430) find_first_route: No Route headers found
4(12430) loose_route: There is no Route HF
4(12430) DEBUG: t_check: msg id=12 global id=11 T start=0xffffffff
4(12430) parse_headers: flags=ffffffffffffffff
4(12430) parse_headers: flags=78
4(12430) t_lookup_request: start searching: hash=18675, isACK=1
4(12430) DEBUG: RFC3261 transaction matched, tid=1BCF7778
4(12430) DEBUG: t_lookup_request: transaction found (T=0xb60dffe0)
4(12430) DEBUG: t_check: msg id=12 global id=12 T end=0xb60dffe0
4(12430) parse_headers: flags=40
4(12430) Warning: sl_send_reply: I won't send a reply for ACK!!
4(12430) ERROR: Error while sending reply
4(12430) DEBUG:destroy_avp_list: destroying list (nil)
4(12430) receive_msg: cleaning up
10(12436) DEBUG: timer routine:1,tl=0xb60e1d44 next=0xb60e010c
10(12436) DEBUG: timer routine:1,tl=0xb60e010c next=(nil)
10(12436) DEBUG: timer routine:4,tl=0xb60e1cc8 next=0xb60e0090
10(12436) DEBUG: retransmission_handler : reply resending (t=0xb60e1c18, SIP/2.0 4 ... )
10(12436) 3(12429) SIP Request:
3(12429) method: <ACK>
3(12429) uri: <sip:testuser_b@generaltests.genericdomain>
DEBUG:tm:t_retransmit_reply: buf=0x642a80: SIP/2.0 4..., shmem=0xb60e3f70: SIP/2.0 4
10(12436) DEBUG: add_to_tail_of_timer[5]: 0xb60e1cc8
10(12436) DEBUG: retransmission_handler : done
10(12436) DEBUG: timer routine:4,tl=0xb60e0090 next=0xb60e5f34
10(12436) DEBUG: retransmission_handler : reply resending (t=0xb60dffe0, SIP/2.0 4 ... )
3(12429) version: <SIP/2.0>
3(12429) parse_headers: flags=2
3(12429) Found param type 232, <branch> = <z9hG4bK3f84.a2d5c811.0>; state=16
3(12429) end of header reached, state=5
3(12429) parse_headers: Via found, flags=2
3(12429) parse_headers: this is the first via
3(12429) After parse_msg...
3(12429) preparing to run routing scripts...
3(12429) DEBUG : sl_filter_ACK: to late to be a local ACK!
10(12436) 3(12429) parse_headers: flags=100
3(12429) DEBUG: add_param: tag=1F5CE0A1
3(12429) DEBUG:parse_to:end of header reached, state=29
3(12429) DEBUG: get_hdr_field: <To> [83]; uri=[sip:testuser_b@generaltests.genericdomain]
3(12429) DEBUG:tm:t_retransmit_reply: buf=0x642a80: SIP/2.0 4..., shmem=0xb60e1530: SIP/2.0 4
DEBUG: to body ["testuser_b" <sip:testuser_b@generaltests.genericdomain>]
3(12429) get_hdr_field: cseq <CSeq>: <640> <ACK>
3(12429) DEBUG: get_hdr_body : content_length=0
3(12429) found end of header
3(12429) DEBUG: is_maxfwd_present: max_forwards header not found!
3(12429) DEBUG: add_param: tag=1AE725BF
3(12429) DEBUG:parse_to:end of header reached, state=29
3(12429) parse_headers: flags=200
3(12429) find_first_route: No Route headers found
3(12429) loose_route: There is no Route HF
3(12429) DEBUG: t_check: msg id=14 global id=13 T start=0xffffffff
3(12429) parse_headers: flags=ffffffffffffffff
3(12429) parse_headers: flags=78
3(12429) t_lookup_request: start searching: hash=18675, isACK=1
3(12429) DEBUG: RFC3261 transaction matched, tid=3f84.a2d5c811.0
3(12429) DEBUG: t_lookup_request: transaction found (T=0xb60e1c18)
3(12429) DEBUG: t_check: msg id=14 global id=14 T end=0xb60e1c18
3(12429) parse_headers: flags=40
10(12436) DEBUG: add_to_tail_of_timer[5]: 0xb60e0090
10(12436) DEBUG: retransmission_handler : done
10(12436) DEBUG: timer routine:4,tl=0xb60e5f34 next=0xb60e44a4
10(12436) DEBUG: timer routine:4,tl=0xb60e44a4 next=(nil)