Summary: | ASTERISK-22551: Session timer : UAS (Asterisk) starts counting at Invite, UAC starts counting at 200 OK. | ||||||
Reporter: | i2045 (i2045) | Labels: | |||||
Date Opened: | 2013-09-18 11:27:06 | Date Closed: | 2014-05-27 17:28:48 | ||||
Priority: | Major | Regression? | |||||
Status: | Closed/Complete | Components: | Channels/chan_sip/General | ||||
Versions: | 1.8.23.0 1.8.23.1 | Frequency of Occurrence | |||||
Related Issues: |
| ||||||
Environment: | Attachments: | ( 0) ASTERISK-22551_Asterisk_debug.txt ( 1) ASTERISK-22551_extensions.conf ( 2) ASTERISK-22551_SIP_signalling.txt ( 3) ASTERISK-22551_sip.conf ( 4) INVITE-test-session-refresher-uac.xml | |||||
Description: | 10.3.25.10 = SIPp (UAC initiating the call) - A leg
10.1.0.19 = Asterisk 1.8.23.1 (UAS) 212.79.111.155 = An echo test client to terminate this call - B leg - 18:09:41 An Invite from UAC (SIPp) to UAS (Asterisk 1.8.23.1) with: Session-Expires: 90;refresher=uac. Min-SE: 90. Supported: timer. Asterisk now starts counting the session timer: [Sep 18 18:09:41] DEBUG[21544]: chan_sip.c:23505 handle_request_invite: Incoming INVITE with 'timer' option supported [Sep 18 18:09:41] DEBUG[21544]: chan_sip.c:23514 handle_request_invite: INVITE also has "Session-Expires" header. [Sep 18 18:09:41] DEBUG[21544]: chan_sip.c:26871 parse_session_expires: Session-Expires: 90 [Sep 18 18:09:41] DEBUG[21544]: chan_sip.c:26884 parse_session_expires: Refresher: UAC [Sep 18 18:09:41] DEBUG[21544]: chan_sip.c:23531 handle_request_invite: INVITE also has "Min-SE" header. [Sep 18 18:09:41] DEBUG[21544]: chan_sip.c:26841 parse_minse: Received Min-SE: 90 [Sep 18 18:09:41] DEBUG[21544]: chan_sip.c:26755 start_session_timer: Session timer started: 1 - 24@10.3.25.10 60000ms This means that Asterisk is terminating the session if no refresh was received before: 18:09:41 + (2/3 * 90) = 18:10:41. - 18:09:41 Asterisk responds to the UAC: "100 Trying" followed by "180 Ringing". - 18:10:01 Asterisk responds "200 OK" to the UAC with: Supported: replaces, timer. Session-Expires: 90;refresher=uac. Require: timer. The UAC now starts counting the session timer. 20 seconds later than Asterisk. This means that the UAC plans to refresh the session at: 18:10:01 + (90 / 2) = 18:10:46. 5 seconds later than Asterisk. - 18:10:41 Asterisk terminates the session as planned, 60 seconds after receiving the initial Invite. [Sep 18 18:10:41] DEBUG[21544]: chan_sip.c:26771 proc_session_timer: Session timer expired: 1 - 24@10.3.25.10 [Sep 18 18:10:41] WARNING[21544]: chan_sip.c:26792 proc_session_timer: Session-Timer expired - 24@10.3.25.10 [Sep 18 18:10:41] DEBUG[21544]: channel.c:2735 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/infromclient-00000000' [Sep 18 18:10:41] DEBUG[21544]: chan_sip.c:26812 proc_session_timer: Session timer stopped: 1 - 24@10.3.25.10 [Sep 18 18:10:41] DEBUG[21544]: chan_sip.c:26707 stop_session_timer: Session timer stopped: -1 - 24@10.3.25.10 - 18:10:46 The UAC would send the session refresh at this time (45 seconds after receiving the "200 OK") but the session is already gone so this doesn't happen... This issue was not present in Asterisk 1.8.22.0. I tested with Asterisk 1.8.23.1 + make samples and modified only sip.conf and extensions.conf, both are attached. Also Asterisk debug logging and the SIP signalling is attached. Reading RFC4028 i think the UAC is right to start counting the session timer at the time of receiving the "200 OK". Is this correct? | ||||||
Comments: | By: Alec Davis (alecdavis) 2013-09-19 05:31:26.928-0500 RE: 1.8.22 I think it would fail as well if the call was answered 30 seconds later (thus the 200 OK was sent at 50 seconds after the invite (instead of 20)). {noformat} 18:09:41 chan_sip.c:26755 start_session_timer: Session timer started: 1 - 24@10.3.25.10 90000ms This means that Asterisk is terminating the session if no refresh was received before: 18:09:41 + 90 = 18:11:11. 18:09:41 Asterisk responds to the UAC: "100 Trying" followed by "180 Ringing". 18:10:31 Asterisk responds "200 OK" to the UAC with: Supported: replaces, timer. Session-Expires: 90;refresher=uac. Require: timer. The UAC now starts counting the session timer. 45 seconds later than Asterisk. This means that the UAC plans to refresh the session at: 18:10:31 + (90 / 2) = 18:11:16. 5 seconds later than Asterisk. 18:11:11 Asterisk terminates the session as planned, 90 seconds after receiving the initial Invite. {noformat} But I agree, reading RFC 4028, that the refresher should be started/restarted after each 2XX is sent. See below; RFC 4028 End of section 9: The session interval is set to the value of the delta-time from the Session-Expires header field in the most recent 2xx response to a session refresh request on that dialog. By: i2045 (i2045) 2013-11-01 10:06:08.848-0500 Because a lot of UAC's connected to my Asterisk server now have a timer set at 90 seconds i am stuck at 1.8.22. With the fix for ASTERISK-21742 (implemented in 1.8.23<) alone the behaviour of Session Timers has not improved in my opinion. I suggest that the fix for ASTERISK-21742 is implemented at the same time as the fix for this issue. I would like to know your opinion about this suggestion. Thanks in advance. By: Walter Doekes (wdoekes) 2014-05-21 07:21:36.203-0500 Just noticed the same issue. To reproduce: {noformat} ; The session expiration is the time of transmission of ; the last 2xx response to a session refresh request on that dialog ; plus the session interval. ; [...] ; It is RECOMMENDED that this refresh be sent once ; half the session interval has elapsed. exten => wait_a_while,1,Ringing() ;; time is now 00:00 same => n,Wait(30) ;; time is now 00:30 same => n,Answer() ;; if time is 00:30 + 90/2, it's refresh time: 01:15 ;; however, asterisk thinks it's disconnect time ;; at: 00:00 + 90 - min(90/3, 32) = 00:58 same => n,Wait(65) ;; time is now 01:35 and we should have done one refresh same => n,Hangup() {noformat} And use the attached {{invite-and-refresh-and-bye.xml}} By: Walter Doekes (wdoekes) 2014-05-23 04:52:08.623-0500 Updated the SIPp XML to test against a patched asterisk. |