WR State timeouts imprecise
It seems that the timeouts of the WR States are not precise... I run
WSMG_024 with wrStateRetry=4 and wrTimeout=300ms (timeout 1200ms). The
WSMG_024 tests timeout of the LOCKED state,
the state is entered and then re-entered times and the LOCKED message
sent at:
diag-frames-1-wri1-raw: SENT 56 bytes at 1523329959.747531216
(signaling)
diag-frames-1-wri1-raw: SENT 56 bytes at 1523329960.066545968
(signaling)
diag-frames-1-wri1-raw: SENT 56 bytes at 1523329960.385435584
(signaling)
diag-frames-1-wri1-raw: SENT 56 bytes at 1523329960.704479536
(signaling)
The CALIBRATE message is received at
diag-frames-1-wri1-raw: RECV 62 bytes at 1523329960.975801264 (type c,
signaling)
1523329960.975801264 - 1523329959.747531216 = 1228 ms
So, the timeout should have expired.
the question is: do we need to be so precise? can we be precise enough?
full log:
diag-extension-2-wri1-raw: hook: wr_execute_slave
diag-fsm-1-wri1-raw: 1523329959.629: LEAVE listening (next: 100)
diag-fsm-1-wri1-raw: 1523329959.641: ENTER uncalibrated/wr-present,
packet len 0
send: TIME: (1523329959 - 0x5acc2ba7) 03:12:39.641928
send: ETH: 88f7 (64:fb:81:2f:f6:ee -> 01:1b:19:00:00:00)
send: VERSION: 2 (type 12, len 56, domain 0)
send: FLAGS: 0x0000 (correction 00000000)
send: PORT: 64-fb-81-ff-fe-2f-f6-ee-00-01
send: REST: seq 0, ctrl 5, log-interval 0
send: MESSAGE: (G) SIGNALING
send: MSG-SIGNALING: target-port 04-f4-bc-ff-fe-58-ba-40-00-00
send: TLV: type 0003 len 12 oui 08:00:30 sub de:ad:01
send: TLV: tlv-content (size 2)
send: TLV: 10 00
send: DUMP: payload (size 56)
send: DUMP: 0c 02 00 38 00 00 00 00 00 00 00 00 00 00 00 00
send: DUMP: 00 00 00 00 64 fb 81 ff fe 2f f6 ee 00 01 00 00
send: DUMP: 05 00 04 f4 bc ff fe 58 ba 40 00 00 00 03 00 08
send: DUMP: 08 00 30 de ad 01 10 00
diag-time-1-wri1-raw: send stamp: (correct 1) 1523329959.641928608
diag-frames-1-wri1-raw: SENT 56 bytes at 1523329959.641928608
(signaling)
diag-extension-2-wri1-raw: hook: wr_execute_slave
diag-fsm-1-wri1-raw: 1523329959.647: uncalibrated/wr-present: reenter in
300 ms
recv: TIME: (1523329959 - 0x5acc2ba7) 03:12:39.662035
recv: ETH: 88f7 (04:f4:bc:58:ba:40 -> 01:1b:19:00:00:00)
recv: VERSION: 2 (type 12, len 56, domain 0)
recv: FLAGS: 0x0000 (correction 00000000)
recv: PORT: 04-f4-bc-ff-fe-58-ba-40-00-00
recv: REST: seq 1, ctrl 5, log-interval 127
recv: MESSAGE: (G) SIGNALING
recv: MSG-SIGNALING: target-port 64-fb-81-ff-fe-2f-f6-ee-00-01
recv: TLV: type 0003 len 12 oui 08:00:30 sub de:ad:01
recv: TLV: tlv-content (size 2)
recv: TLV: 10 01
recv: DUMP: payload (size 56)
recv: DUMP: 0c 02 00 38 00 00 00 00 00 00 00 00 00 00 00 00
recv: DUMP: 00 00 00 00 04 f4 bc ff fe 58 ba 40 00 00 00 01
recv: DUMP: 05 7f 64 fb 81 ff fe 2f f6 ee 00 01 00 03 00 08
recv: DUMP: 08 00 30 de ad 01 10 01
diag-time-1-wri1-raw: recv stamp: (correct 1) 1523329959.662035952
diag-frames-1-wri1-raw: RECV 56 bytes at 1523329959.662035952 (type c,
signaling)
diag-extension-2-wri1-raw: hook: wr_execute_slave
diag-fsm-1-wri1-raw: 1523329959.667: LEAVE uncalibrated/wr-present
(next: 101)
diag-fsm-1-wri1-raw: 1523329959.679: ENTER uncalibrated/wr-s-lock,
packet len 0
diag-time-1-wri1-raw: Start locking
diag-time-2-wri1-raw: PLL is locked
diag-fsm-1-wri1-raw: 1523329959.722: LEAVE uncalibrated/wr-s-lock (next:
103)
diag-fsm-1-wri1-raw: 1523329959.734: ENTER uncalibrated/wr-locked,
packet len 0
send: TIME: (1523329959 - 0x5acc2ba7) 03:12:39.747531
send: ETH: 88f7 (64:fb:81:2f:f6:ee -> 01:1b:19:00:00:00)
send: VERSION: 2 (type 12, len 56, domain 0)
send: FLAGS: 0x0000 (correction 00000000)
send: PORT: 64-fb-81-ff-fe-2f-f6-ee-00-01
send: REST: seq 0, ctrl 5, log-interval 0
send: MESSAGE: (G) SIGNALING
send: MSG-SIGNALING: target-port 04-f4-bc-ff-fe-58-ba-40-00-00
send: TLV: type 0003 len 12 oui 08:00:30 sub de:ad:01
send: TLV: tlv-content (size 2)
send: TLV: 10 02
send: DUMP: payload (size 56)
send: DUMP: 0c 02 00 38 00 00 00 00 00 00 00 00 00 00 00 00
send: DUMP: 00 00 00 00 64 fb 81 ff fe 2f f6 ee 00 01 00 00
send: DUMP: 05 00 04 f4 bc ff fe 58 ba 40 00 00 00 03 00 08
send: DUMP: 08 00 30 de ad 01 10 02
diag-time-1-wri1-raw: send stamp: (correct 1) 1523329959.747531216
diag-frames-1-wri1-raw: SENT 56 bytes at 1523329959.747531216
(signaling)
diag-fsm-1-wri1-raw: 1523329959.753: uncalibrated/wr-locked: reenter in
300 ms
diag-time-1-wri1-raw: timeout expired:
diag-extension-1-wri1-raw: Retry on timeout
send: TIME: (1523329960 - 0x5acc2ba8) 03:12:40.066545
send: ETH: 88f7 (64:fb:81:2f:f6:ee -> 01:1b:19:00:00:00)
send: VERSION: 2 (type 12, len 56, domain 0)
send: FLAGS: 0x0000 (correction 00000000)
send: PORT: 64-fb-81-ff-fe-2f-f6-ee-00-01
send: REST: seq 0, ctrl 5, log-interval 0
send: MESSAGE: (G) SIGNALING
send: MSG-SIGNALING: target-port 04-f4-bc-ff-fe-58-ba-40-00-00
send: TLV: type 0003 len 12 oui 08:00:30 sub de:ad:01
send: TLV: tlv-content (size 2)
send: TLV: 10 02
send: DUMP: payload (size 56)
send: DUMP: 0c 02 00 38 00 00 00 00 00 00 00 00 00 00 00 00
send: DUMP: 00 00 00 00 64 fb 81 ff fe 2f f6 ee 00 01 00 00
send: DUMP: 05 00 04 f4 bc ff fe 58 ba 40 00 00 00 03 00 08
send: DUMP: 08 00 30 de ad 01 10 02
diag-time-1-wri1-raw: send stamp: (correct 1) 1523329960.066545968
diag-frames-1-wri1-raw: SENT 56 bytes at 1523329960.066545968
(signaling)
diag-fsm-1-wri1-raw: 1523329960.072: uncalibrated/wr-locked: reenter in
300 ms
diag-time-1-wri1-raw: timeout expired:
diag-extension-1-wri1-raw: Retry on timeout
send: TIME: (1523329960 - 0x5acc2ba8) 03:12:40.385435
send: ETH: 88f7 (64:fb:81:2f:f6:ee -> 01:1b:19:00:00:00)
send: VERSION: 2 (type 12, len 56, domain 0)
send: FLAGS: 0x0000 (correction 00000000)
send: PORT: 64-fb-81-ff-fe-2f-f6-ee-00-01
send: REST: seq 0, ctrl 5, log-interval 0
send: MESSAGE: (G) SIGNALING
send: MSG-SIGNALING: target-port 04-f4-bc-ff-fe-58-ba-40-00-00
send: TLV: type 0003 len 12 oui 08:00:30 sub de:ad:01
send: TLV: tlv-content (size 2)
send: TLV: 10 02
send: DUMP: payload (size 56)
send: DUMP: 0c 02 00 38 00 00 00 00 00 00 00 00 00 00 00 00
send: DUMP: 00 00 00 00 64 fb 81 ff fe 2f f6 ee 00 01 00 00
send: DUMP: 05 00 04 f4 bc ff fe 58 ba 40 00 00 00 03 00 08
send: DUMP: 08 00 30 de ad 01 10 02
diag-time-1-wri1-raw: send stamp: (correct 1) 1523329960.385435584
diag-frames-1-wri1-raw: SENT 56 bytes at 1523329960.385435584
(signaling)
diag-fsm-1-wri1-raw: 1523329960.391: uncalibrated/wr-locked: reenter in
300 ms
diag-time-1-wri1-raw: timeout expired:
diag-extension-1-wri1-raw: Retry on timeout
send: TIME: (1523329960 - 0x5acc2ba8) 03:12:40.704479
send: ETH: 88f7 (64:fb:81:2f:f6:ee -> 01:1b:19:00:00:00)
send: VERSION: 2 (type 12, len 56, domain 0)
send: FLAGS: 0x0000 (correction 00000000)
send: PORT: 64-fb-81-ff-fe-2f-f6-ee-00-01
send: REST: seq 0, ctrl 5, log-interval 0
send: MESSAGE: (G) SIGNALING
send: MSG-SIGNALING: target-port 04-f4-bc-ff-fe-58-ba-40-00-00
send: TLV: type 0003 len 12 oui 08:00:30 sub de:ad:01
send: TLV: tlv-content (size 2)
send: TLV: 10 02
send: DUMP: payload (size 56)
send: DUMP: 0c 02 00 38 00 00 00 00 00 00 00 00 00 00 00 00
send: DUMP: 00 00 00 00 64 fb 81 ff fe 2f f6 ee 00 01 00 00
send: DUMP: 05 00 04 f4 bc ff fe 58 ba 40 00 00 00 03 00 08
send: DUMP: 08 00 30 de ad 01 10 02
diag-time-1-wri1-raw: send stamp: (correct 1) 1523329960.704479536
diag-frames-1-wri1-raw: SENT 56 bytes at 1523329960.704479536
(signaling)
diag-fsm-1-wri1-raw: 1523329960.709: uncalibrated/wr-locked: reenter in
300 ms
recv: TIME: (1523329960 - 0x5acc2ba8) 03:12:40.961751
recv: ETH: 88f7 (04:f4:bc:58:ba:40 -> 01:1b:19:00:00:00)
recv: VERSION: 2 (type 11, len 78, domain 0)
recv: FLAGS: 0x0000 (correction 00000000)
recv: PORT: 04-f4-bc-ff-fe-58-ba-40-00-00
recv: REST: seq 5, ctrl 5, log-interval 127
recv: MESSAGE: (G) ANNOUNCE
recv: MSG-ANNOUNCE: stamp 1535028655.000000000
recv: MSG-ANNOUNCE: grandmaster-quality 00-00-0000
recv: MSG-ANNOUNCE: grandmaster-prio 127 0
recv: MSG-ANNOUNCE: grandmaster-id 00-00-00-00-03-00-0a-08
recv: TLV: type 0003 len 14 oui 08:00:30 sub de:ad:01
recv: TLV: tlv-content (size 4)
recv: TLV: 20 00 00 07
recv: DUMP: payload (size 78)
recv: DUMP: 0b 02 00 4e 00 00 00 00 00 00 00 00 00 00 00 00
recv: DUMP: 00 00 00 00 04 f4 bc ff fe 58 ba 40 00 00 00 05
recv: DUMP: 05 7f 00 00 5b 7e ad af 00 00 00 00 00 00 00 7f
recv: DUMP: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
recv: DUMP: 00 03 00 0a 08 00 30 de ad 01 20 00 00 07
diag-time-1-wri1-raw: recv stamp: (correct 1) 1523329960.961751120
diag-frames-1-wri1-raw: RECV 78 bytes at 1523329960.961751120 (type b,
announce)
diag-fsm-1-wri1-raw: 1523329960.969: uncalibrated/wr-locked: reenter in
300 ms
recv: TIME: (1523329960 - 0x5acc2ba8) 03:12:40.975801
recv: ETH: 88f7 (04:f4:bc:58:ba:40 -> 01:1b:19:00:00:00)
recv: VERSION: 2 (type 12, len 62, domain 0)
recv: FLAGS: 0x0000 (correction 00000000)
recv: PORT: 04-f4-bc-ff-fe-58-ba-40-00-00
recv: REST: seq 1, ctrl 5, log-interval 127
recv: MESSAGE: (G) SIGNALING
recv: MSG-SIGNALING: target-port 64-fb-81-ff-fe-2f-f6-ee-00-01
recv: TLV: type 0003 len 18 oui 08:00:30 sub de:ad:01
recv: TLV: tlv-content (size 8)
recv: TLV: 10 03 00 00 00 00 0b b8
recv: DUMP: payload (size 62)
recv: DUMP: 0c 02 00 3e 00 00 00 00 00 00 00 00 00 00 00 00
recv: DUMP: 00 00 00 00 04 f4 bc ff fe 58 ba 40 00 00 00 01
recv: DUMP: 05 7f 64 fb 81 ff fe 2f f6 ee 00 01 00 03 00 0e
recv: DUMP: 08 00 30 de ad 01 10 03 00 00 00 00 0b b8
diag-time-1-wri1-raw: recv stamp: (correct 1) 1523329960.975801264
diag-frames-1-wri1-raw: RECV 62 bytes at 1523329960.975801264 (type c,
signaling)
diag-fsm-1-wri1-raw: 1523329960.996: LEAVE uncalibrated/wr-locked (next:
106)
diag-fsm-1-wri1-raw: 1523329961.007: ENTER wr-resp-calib-req, packet len
0
diag-fsm-1-wri1-raw: 1523329961.008: wr-resp-calib-req: reenter in 300
ms
diag-time-1-wri1-raw: timeout expired:
diag-extension-1-wri1-raw: Retry on timeout
diag-fsm-1-wri1-raw: 1523329961.320: wr-resp-calib-req: reenter in 300
ms
diag-time-1-wri1-raw: timeout expired:
diag-extension-1-wri1-raw: Retry on timeout
diag-fsm-1-wri1-raw: 1523329961.634: wr-resp-calib-req: reenter in 300
ms
diag-time-1-wri1-raw: timeout expired:
diag-extension-1-wri1-raw: Retry on timeout
diag-fsm-1-wri1-raw: 1523329961.946: wr-resp-calib-req: reenter in 300
ms
recv: TIME: (1523329961 - 0x5acc2ba9) 03:12:41.970538
recv: ETH: 88f7 (04:f4:bc:58:ba:40 -> 01:1b:19:00:00:00)
recv: VERSION: 2 (type 11, len 78, domain 0)
recv: FLAGS: 0x0000 (correction 00000000)
recv: PORT: 04-f4-bc-ff-fe-58-ba-40-00-00
recv: REST: seq 6, ctrl 5, log-interval 127