12:02:27.395 Running procedure: 8.22.2.15
12:02:27.400 This procedure is enabled because the following options:
12:02:27.400 - supports.doubleBitChangeEvents == true
12:02:27.400 - timesync.binaryInputChangeWithRelativeTime == true
12:02:27.400 step: 1
12:02:27.400 - Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x01
12:02:27.400 - g4v0, All Objects
12:02:27.401 --A-> Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x01
12:02:27.401 g4v0, All Objects
12:02:27.402 --T-> fir: 1 fin: 1 seq: 0
12:02:27.402 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 11 dest: 1024 src: 1
12:02:27.402 --P-> 05 64 0B C4 00 04 01 00 CA 8A
12:02:27.402 C0 C1 01 04 00 06 05 23
12:02:27.403 steps: 2 to 3
12:02:27.403 - Read a single fragment response w/ sequence(0x01)
12:02:27.403 - If the response is not Null, verify that the device requests an application layer confirmation.
12:02:27.404 <-P-- 05 64 0A 44 01 00 00 04 67 88
12:02:27.404 C0 C1 81 90 00 73 EE
12:02:27.404 <-L-- master: 0 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0x44 length: 10 dest: 1 src: 1024
12:02:27.405 <-T-- fir: 1 fin: 1 seq: 0
12:02:27.405 <-A-- Response(0x81) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x01 IIN(DeviceRestart, NeedTime)
12:02:27.406 step: 4
12:02:27.406 - Generate several Double-bit Binary Input Change Events
12:02:27.406 Updated DBBI 41: value=DETERMINED_OFF, flags=41, timestamp=DNPTime(1586534547406)
12:02:27.406 Updated DBBI 65535: value=DETERMINED_OFF, flags=41, timestamp=DNPTime(1586534547406)
12:02:27.407 Updated DBBI 1024: value=DETERMINED_ON, flags=81, timestamp=DNPTime(1586534547406)
12:02:27.407 step: 5
12:02:27.407 - Wait for 65536 milliseconds
12:03:32.943 step: 6
12:03:32.943 - Generate several Double-bit Binary Input Change Events
12:03:32.944 Updated DBBI 41: value=DETERMINED_ON, flags=81, timestamp=DNPTime(1586534612943)
12:03:32.944 Updated DBBI 1024: value=DETERMINED_OFF, flags=41, timestamp=DNPTime(1586534612944)
12:03:32.944 Updated DBBI 1024: value=DETERMINED_ON, flags=81, timestamp=DNPTime(1586534612944)
12:03:32.945 step: 7
12:03:32.945 - Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x02
12:03:32.945 - g4v3, All Objects
12:03:32.946 --A-> Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x02
12:03:32.946 g4v3, All Objects
12:03:32.946 --T-> fir: 1 fin: 1 seq: 0
12:03:32.946 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 11 dest: 1024 src: 1
12:03:32.947 --P-> 05 64 0B C4 00 04 01 00 CA 8A
12:03:32.947 C0 C2 01 04 03 06 A4 F6
12:03:32.950 steps: 8 to 14
12:03:32.950 - Read a single fragment response w/ sequence(0x02)
12:03:32.950 - Verify the device responds with previous data followed by the new events in time order
12:03:32.950 - If the variation contains timestamps, verify that they are reasonable according to the resolution specified in the Device Profile
12:03:32.950 - Verify that an application layer confirmation is requested.
12:03:32.950 - Validate that a g51v1 or g51v2 precedes the g4v3 in each fragment of the response
12:03:32.950 - Validation that only g51v1, g51v2 and g4v3 appears in the response
12:03:32.950 - Validate that each group of events that occurred more than 0xFFFF milliseconds apart are preceded by a new CTO object
12:03:32.950 - Verify that flag behavior complies with Section 2, Note #5.
12:03:32.952 <-P-- 05 64 46 44 01 00 00 04 A8 F1
12:03:32.952 C1 E2 81 90 00 33 02 07 01 CE FF D3 64 71 01 04 51 D1
12:03:32.952 03 28 03 00 29 00 41 00 00 FF FF 41 00 00 00 04 57 9B
12:03:32.952 81 00 00 33 02 07 01 CF FF D4 64 71 01 04 03 28 7D F5
12:03:32.952 03 00 29 00 81 00 00 00 04 41 01 00 00 04 81 01 5D B1
12:03:32.952 00 FF FF
12:03:32.952 <-L-- master: 0 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0x44 length: 70 dest: 1 src: 1024
12:03:32.952 <-T-- fir: 1 fin: 1 seq: 1
12:03:32.956 <-A-- Response(0x81) fir: 1 fin: 1 con: 1 uns: 0 seq: 0x02 IIN(DeviceRestart, NeedTime)
12:03:32.956 g51v2, 1-Byte Count, count: 1
12:03:32.956 time: 1586534547406
12:03:32.956 g4v3, 2-Byte Count and Index, count: 3
12:03:32.956 [41] - flags: 0x41 cto: 0
12:03:32.956 [65535] - flags: 0x41 cto: 0
12:03:32.956 [1024] - flags: 0x81 cto: 0
12:03:32.956 g51v2, 1-Byte Count, count: 1
12:03:32.956 time: 1586534612943
12:03:32.956 g4v3, 2-Byte Count and Index, count: 3
12:03:32.956 [41] - flags: 0x81 cto: 0
12:03:32.956 [1024] - flags: 0x41 cto: 1
12:03:32.956 [1024] - flags: 0x81 cto: 1
12:03:32.956 --A-> Confirm(0x00) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x02
12:03:32.956 --T-> fir: 1 fin: 1 seq: 0
12:03:32.956 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 8 dest: 1024 src: 1
12:03:32.957 --P-> 05 64 08 C4 00 04 01 00 9A 19
12:03:32.957 C0 C2 00 D6 8D
12:03:32.958 step: 15
12:03:32.958 - Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x03
12:03:32.958 - g4v0, All Objects
12:03:32.959 --A-> Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x03
12:03:32.959 g4v0, All Objects
12:03:32.959 --T-> fir: 1 fin: 1 seq: 0
12:03:32.959 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 11 dest: 1024 src: 1
12:03:32.960 --P-> 05 64 0B C4 00 04 01 00 CA 8A
12:03:32.960 C0 C3 01 04 00 06 09 65
12:03:32.961 step: 16
12:03:32.961 - Read a single fragment response w/ sequence(0x03)
12:03:32.961 - Verify that the response is empty
12:03:32.962 <-P-- 05 64 0A 44 01 00 00 04 67 88
12:03:32.962 C2 C3 81 90 00 D6 60
12:03:32.962 <-L-- master: 0 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0x44 length: 10 dest: 1 src: 1024
12:03:32.962 <-T-- fir: 1 fin: 1 seq: 2
12:03:32.962 <-A-- Response(0x81) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x03 IIN(DeviceRestart, NeedTime)
12:03:32.963 Passed procedure: 8.22.2.15