ably-cocoa icon indicating copy to clipboard operation
ably-cocoa copied to clipboard

Connection sometimes performs extra retry when it should transition to `SUSPENDED` state

Open lawrence-forooghian opened this issue 1 year ago • 2 comments

Issue description

ARTRealtime will sometimes perform one more connection retry than it should — that is, it will perform a connection retry after connectionStateTtl has been exceeded, violating RTN14e.

Steps to reproduce

The steps vary depending on whether you're viewing the code before or after PR #1613, which made some test changes.

  • Before PR #1613: change expectedTime in test test__059__Connection__connection_request_fails__connection_attempt_fails_for_any_recoverable_reason from 3.0 to 4.9, and run the test a few times.
  • After PR #1613: change the XCTAssertGreaterThanOrEqual relating to the number of observed retries to an XCAssertEqual.

Observed behaviour

The test fails because one more retry than expected was made.

Underlying issue

By adding logging to ARTRealtime (see 6f738c5134562ff9889205e4c54803051b4269c6), we see the following messages:

2023-07-05 14:12:19.420393-0300 xctest[29178:1697374] VERBOSE: (ARTRealtime.m:674) RT:0x102d045a0 set connection lost time; expected suspension at 2023-07-05T17:12:24.320Z (ttl=4.900000)
2023-07-05 14:12:19.316145-0300 xctest[29178:1696902] VERBOSE: (ARTRealtime.m:1099) Scheduling timeout work in transportConnectForcingNewToken:newConnection:
2023-07-05 14:12:20.453626-0300 xctest[29178:1697372] VERBOSE: (ARTRealtime.m:1099) Scheduling timeout work in transportConnectForcingNewToken:newConnection:
2023-07-05 14:12:21.616243-0300 xctest[29178:1697374] VERBOSE: (ARTRealtime.m:1099) Scheduling timeout work in transportConnectForcingNewToken:newConnection:
2023-07-05 14:12:22.745132-0300 xctest[29178:1697374] VERBOSE: (ARTRealtime.m:1099) Scheduling timeout work in transportConnectForcingNewToken:newConnection:
2023-07-05 14:12:23.882761-0300 xctest[29178:1697374] VERBOSE: (ARTRealtime.m:1099) Scheduling timeout work in transportConnectForcingNewToken:newConnection:
2023-07-05 14:12:25.046635-0300 xctest[29178:1697372] VERBOSE: (ARTRealtime.m:1099) Scheduling timeout work in transportConnectForcingNewToken:newConnection:

Notice that the final "Scheduling timeout work" log message occurs after the date described by the "expected suspension at" log message. This suggests that the connection is only checking whether it should enter SUSPENDED in the moment that a timeout occurs, and not before scheduling work that might time out.

┆Issue is synchronized with this Jira Bug by Unito

lawrence-forooghian avatar Jul 05 '23 14:07 lawrence-forooghian