Check correction of the DPA timing

[spinarr]

• Must be confirmed that default timing is working fine
• Tests with bigger IQRF network (100-150) to be done

[spinarr]

• TEST1

• Simple test has been created and timing checked with smaller network(10nodes) for now

• Simple test: Creates first DPA transaction(LEDR pulse) and send it to node10. Right after that without any user app waiting creating next DPA transaction and send it to node9.

• Results: First DPA request SENT: 17:04:31.131480 Second DPA request SENT: 17:04:32.150336 DIFF: ~1020ms

First transaction: REQ: 0a 00 06 03 ff ff ......
CONF: 0a 00 06 03 ff ff ff 32 0a(hops) 08(timeslot) 0a(hops back) .......2... RESP: 0a 00 06 83 0f 00 00 3d .......=

• Time to wait before user app can sent another request (start next DPA transaction) to the network

Time the DPA confirmation was received + ( Hops + 1 ) × Timeslot length × 10 ms + ( Hops Response + 1 ) × Actual response timeslot length × 10 ms

=> 40 + ((10+1)80)=880 + ((10+1) 80)=880 = ~1800 ms (must waits before next request goes to the network)

[spinarr]

• TEST2

• Another test (First DPA transaction does not set user timeout by: dpaHandler->Timeout(timeout) & Second transaction does set user timeout by: dpaHandler->Timeout(500))

analysis.txt

1. transaction goes fine wrt timing
2. transaction timing does not seems to be right

22-08-2017 21:11:36.336978 {DBG} "DpaHandler.cpp" ln:104 DpaHandler::ResponseMessageHandler()

Received from IQRF interface: 09 00 06 03 ff ff ff 32 09 08 09 .......2...

22-08-2017 21:11:36.337988 {DBG} "DpaTransfer.cpp" ln:175 DpaTransfer::EstimateLpTimeout() Estimated LP timeout: estimatedTimeoutMs="1940"

22-08-2017 21:11:36.338797 {DBG} "DpaTransfer.cpp" ln:193 DpaTransfer::SetTimeoutForCurrentTransfer() Expected duration :m_expectedDurationMs="2440"

• Why the library adds user timeout(500) to the estimation from confirmation(1940)
• Maybe: if user sets timeout < estimation then use estimation if > use user timeout

22-08-2017 21:11:36.339334 {INF} "DpaTransfer.cpp" ln:95 DpaTransfer::ProcessReceivedMessage() Confirmation processed.

[spinarr]

• TEST3

• Another test: (same scenario as previous test but all nodes (1-10) switched off)

23-08-2017 18:38:40.474952 {DBG} "IqrfCdcChannel.cpp" ln:41 IqrfCdcChannel::sendTo() Sending to IQRF CDC: 0a 00 06 03 ff ff ......

23-08-2017 18:38:40.475111 {DBG} "IqrfCdcChannel.cpp" ln:44 IqrfCdcChannel::sendTo() Trying to sent: 1.1 23-08-2017 18:38:40.483690 {DBG} "DpaHandler.cpp" ln:67 DpaHandler::SendDpaMessage() Default timeout: m_defaultTimeoutMs="-1" 23-08-2017 18:38:40.483850 {DBG} "DpaTransfer.cpp" ln:45 DpaTransfer::ProcessSentMessage() {ENTER} 23-08-2017 18:38:40.483980 {DBG} "DpaTransfer.cpp" ln:182 DpaTransfer::SetTimeoutForCurrentTransfer() {ENTER} 23-08-2017 18:38:40.484192 {DBG} "DpaTransfer.cpp" ln:187 DpaTransfer::SetTimeoutForCurrentTransfer() Expected duration :m_expectedDurationMs="-1" 23-08-2017 18:38:40.484349 {DBG} "DpaTransfer.cpp" ln:61 DpaTransfer::ProcessSentMessage() {LEAVE} 23-08-2017 18:38:40.484470 {DBG} "DpaHandler.cpp" ln:71 DpaHandler::SendDpaMessage() {LEAVE} 23-08-2017 18:38:40.515947 {DBG} "DpaHandler.cpp" ln:104 DpaHandler::ResponseMessageHandler()

Received from IQRF interface: 0a 00 06 03 ff ff ff 3c 0a 08 0a .......<...

23-08-2017 18:38:40.516218 {DBG} "DpaTransfer.cpp" ln:66 DpaTransfer::ProcessReceivedMessage() {ENTER} 23-08-2017 18:38:40.516431 {DBG} "DpaTransfer.cpp" ln:163 DpaTransfer::EstimateLpTimeout() {ENTER} 23-08-2017 18:38:40.516707 {DBG} "DpaTransfer.cpp" ln:175 DpaTransfer::EstimateLpTimeout() Estimated LP timeout: estimatedTimeoutMs="2130" 23-08-2017 18:38:40.516903 {DBG} "DpaTransfer.cpp" ln:176 DpaTransfer::EstimateLpTimeout() {LEAVE} 23-08-2017 18:38:40.517095 {DBG} "DpaTransfer.cpp" ln:182 DpaTransfer::SetTimeoutForCurrentTransfer() {ENTER} 23-08-2017 18:38:40.517307 {DBG} "DpaTransfer.cpp" ln:187 DpaTransfer::SetTimeoutForCurrentTransfer() Expected duration :m_expectedDurationMs="-1" 23-08-2017 18:38:40.517481 {INF} "DpaTransfer.cpp" ln:95 DpaTransfer::ProcessReceivedMessage() Confirmation processed. 23-08-2017 18:38:40.517649 {DBG} "DpaTransfer.cpp" ln:105 DpaTransfer::ProcessReceivedMessage() {LEAVE}

• -1 means waiting forever, but this does not feel right when user does not set user timeout
• Maybe: 1) the estimation from confirmation should be used for waiting by default 2) this can be overrided by the user timeout calling dpaHandler->Timeout(timeout) 3) if user sets dpaHandler->Timeout(-1) then it blocks forever e.g. for discovery calls which can last tens of minuts

[spinarr]

• TEST4

• Another test: (same scenario as previous test but all nodes (1-10) switched off)

• It works fine when user calls dpaHandler->Timeout(timeout)

• But there is still that situations where user timeout is added to estimated timeout so it blocks much longer (2630ms) then it should be according to:

Time the DPA confirmation was received + ( Hops + 1 ) × Timeslot length × 10 ms + ( Hops Response + 1 ) × Actual response timeslot length × 10 ms

=> 40 + ((10+1)80)=880 + ((10+1) 80)=880 = ~1800 ms (must waits before next request goes to the network)

[spinarr]

• TEST5 (Sending two broadcast messages)

Confirmation for the first broadcast request: 23-08-2017 19:25:53.195347 {DBG} "DpaHandler.cpp" ln:104 DpaHandler::ResponseMessageHandler()

Received from IQRF interface: ff 00 06 03 ff ff ff 3c 0a 08 00 .......<...

23-08-2017 19:25:53.195794 {DBG} "DpaTransfer.cpp" ln:175 DpaTransfer::EstimateLpTimeout() Estimated LP timeout: estimatedTimeoutMs="1030"

23-08-2017 19:25:53.196162 {DBG} "DpaTransfer.cpp" ln:193 DpaTransfer::SetTimeoutForCurrentTransfer() Expected duration :m_expectedDurationMs="1029"

...

Sending next brodcast request): 23-08-2017 19:25:53.198295 {DBG} "IqrfCdcChannel.cpp" ln:41 IqrfCdcChannel::sendTo() Sending to IQRF CDC: ff 00 06 03 ff ff ......

• Next broadcast is sent to the network immediately but there is a need to wait before finishing the routing from coordinator to all nodes (1-10):

Time the DPA confirmation was received + ( Hops + 1 ) × Timeslot length × 10 ms => 40 + 880=920ms (must waits before next broadcast request goes to the network)

[spinarr]

Branch feature/review-insteps: https://github.com/iqrfsdk/clibdpa/commit/49a5024bd839f6056b4731b4d8a3fc6e6d2f42cb

• default timeout is 0 (it means timing according to estimation from DPA confirmation)

• timeout -1 means infinite waiting for a message (blocks forever until message arrives)

• user can set timeout by Timeout(userTimeout)

  if userTimeout < estimatedTimeout then estimatedTimeout from confirmation is used

  if userTimeout > estimatedTimeout then userTimeout is used

• logic also waits correct time before next request can be sent (processing DPA response has been added to adjust correct timing)

• example and demo modified

• todo

  handle situation when the DPA request is sent to coordinator (then comes DPA response directly without confirmation)

  handle situation when even DPA confirmation does not arrive

[spinarr]

Summary to this point: https://github.com/iqrfsdk/clibdpa/commit/49c8a2837d7fbcfdf2bd3e87dea5d218cd66d549

• infinite timeout => 0 -- breaks when response comes otherwise no break (todo: must confirm Transaction level)

• default timeout => 200ms (no call DpaHandler->Timeout(userTimeout) is needed) -- breaks after 200ms if there is no confirmation received -- if confirmation then new timeout is set for a response based on estimation if is > 200, if not 200ms stays for response

• user timeout => Timeout(userTimeout) -- if there is no confirmation it breaks after userTimeout -- if userTimeout < estimatedTimeout(from confirmation) then use estimatedTimeout -- if userTimeout > estimatedTimeout(from confirmation) then use userTimeout

• estimatedTimeout is corrected based on length(response.PData) once response arrives and it breaks after correctedTimeout elapses

[spinarr]

TEST1-TEST5 passed with current implementation: https://github.com/iqrfsdk/clibdpa/commit/a2cca8bf23a74272f97adabf7defbbf6824ebd5e Please, review it.