12:01:38.769 Running procedure: 8.15.2
12:01:38.773 This procedure is enabled because the following options:
12:01:38.773 - timesync.binaryInputChangeWithRelativeTime == true
12:01:38.774 step: 1
12:01:38.774 - DUT supports Binary Input Change with Relative Time.
12:01:38.774 step: 2
12:01:38.774 - Cycle power to the DUT
12:01:38.780 step: 3
12:01:38.780 - Write(0x02) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x00
12:01:38.780 - g80v1, 1-Byte Start/Stop, start: 7 stop: 7
12:01:38.780 - [7] - BooleanValue(false)
12:01:38.780 - Read a single fragment response w/ sequence(0x00)
12:01:38.780 - Verify that the response is empty
12:01:38.782 --A-> Write(0x02) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x00
12:01:38.782 g80v1, 1-Byte Start/Stop, start: 7 stop: 7
12:01:38.782 [7] - BooleanValue(false)
12:01:38.782 --T-> fir: 1 fin: 1 seq: 0
12:01:38.782 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 14 dest: 1024 src: 1
12:01:38.783 --P-> 05 64 0E C4 00 04 01 00 43 72
12:01:38.783 C0 C0 02 50 01 00 07 07 00 2C 49
12:01:38.784 <-P-- 05 64 0A 44 01 00 00 04 67 88
12:01:38.784 C0 C0 81 10 00 B4 37
12:01:38.784 <-L-- master: 0 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0x44 length: 10 dest: 1 src: 1024
12:01:38.784 <-T-- fir: 1 fin: 1 seq: 0
12:01:38.785 <-A-- Response(0x81) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x00 IIN(NeedTime)
12:01:38.785 step: 4
12:01:38.785 - Generate several Binary Input Change Events
12:01:38.785 Updated BI 41: value=true, flags=81, timestamp=DNPTime(1586534498785)
12:01:38.786 Updated BI 41: value=false, flags=1, timestamp=DNPTime(1586534498785)
12:01:38.786 Updated BI 1024: value=true, flags=81, timestamp=DNPTime(1586534498786)
12:01:38.787 step: 5
12:01:38.787 - Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x01
12:01:38.787 - g2v3, All Objects
12:01:38.787 --A-> Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x01
12:01:38.787 g2v3, All Objects
12:01:38.788 --T-> fir: 1 fin: 1 seq: 0
12:01:38.788 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 11 dest: 1024 src: 1
12:01:38.789 --P-> 05 64 0B C4 00 04 01 00 CA 8A
12:01:38.789 C0 C1 01 02 03 06 3E C6
12:01:38.791 steps: 6 to 9
12:01:38.791 - Read a single fragment response w/ sequence(0x01)
12:01:38.791 - Validate that a g51v2 precedes the g2v3 in each fragment of the response
12:01:38.791 - Validation that only g51v2 and g2v3 appears in the response
12:01:38.791 - Verify that flag behavior complies with Section 2, Note #5.
12:01:38.791 - Verify that an application layer confirmation is requested.
12:01:38.791 - Verify the device responds with all generated Binary Input events
12:01:38.791 - If the variation contains timestamps, verify that they are reasonable according to the resolution specified in the Device Profile
12:01:38.792 <-P-- 05 64 28 44 01 00 00 04 52 5F
12:01:38.792 C1 E1 81 10 00 33 02 07 01 E1 41 D3 64 71 01 02 F3 15
12:01:38.792 03 28 03 00 29 00 81 00 00 29 00 01 00 00 00 04 A5 1D
12:01:38.792 81 01 00 AE 18
12:01:38.793 <-L-- master: 0 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0x44 length: 40 dest: 1 src: 1024
12:01:38.793 <-T-- fir: 1 fin: 1 seq: 1
12:01:38.795 <-A-- Response(0x81) fir: 1 fin: 1 con: 1 uns: 0 seq: 0x01 IIN(NeedTime)
12:01:38.795 g51v2, 1-Byte Count, count: 1
12:01:38.795 time: 1586534498785
12:01:38.795 g2v3, 2-Byte Count and Index, count: 3
12:01:38.795 [41] - flags: 0x81 cto: 0
12:01:38.795 [41] - flags: 0x01 cto: 0
12:01:38.795 [1024] - flags: 0x81 cto: 1
12:01:38.795 --A-> Confirm(0x00) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x01
12:01:38.795 --T-> fir: 1 fin: 1 seq: 0
12:01:38.796 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 8 dest: 1024 src: 1
12:01:38.796 --P-> 05 64 08 C4 00 04 01 00 9A 19
12:01:38.796 C0 C1 00 7D 3D
12:01:38.797 step: 10
12:01:38.797 - Device supports time synchronization from DNP3 master
12:01:38.798 step: 11
12:01:38.798 - Wait for 5000 milliseconds
12:01:43.799 step: 12
12:01:43.799 - Delay Meas(0x17) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x02
12:01:43.800 --A-> Delay Meas(0x17) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x02
12:01:43.800 --T-> fir: 1 fin: 1 seq: 0
12:01:43.800 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 8 dest: 1024 src: 1
12:01:43.801 --P-> 05 64 08 C4 00 04 01 00 9A 19
12:01:43.801 C0 C2 17 27 BC
12:01:43.803 step: 13
12:01:43.803 - Read a single fragment response w/ sequence(0x02)
12:01:43.803 - Verify valid delay measurement response
12:01:43.803 - Verify that the IIN field contains IIN(NeedTime)
12:01:43.803 <-P-- 05 64 10 44 01 00 00 04 CD 4C
12:01:43.803 C2 C2 81 10 00 34 02 07 01 00 00 DB F7
12:01:43.804 <-L-- master: 0 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0x44 length: 16 dest: 1 src: 1024
12:01:43.804 <-T-- fir: 1 fin: 1 seq: 2
12:01:43.805 <-A-- Response(0x81) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x02 IIN(NeedTime)
12:01:43.805 g52v2, 1-Byte Count, count: 1
12:01:43.805 delay: 0
12:01:43.806 step: 14
12:01:43.806 - Write(0x02) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x03
12:01:43.806 - g50v1, 1-Byte Count, count: 1
12:01:43.806 - time: 1586534498773
12:01:43.807 --A-> Write(0x02) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x03
12:01:43.807 g50v1, 1-Byte Count, count: 1
12:01:43.807 time: 1586534498773
12:01:43.807 --T-> fir: 1 fin: 1 seq: 0
12:01:43.807 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 18 dest: 1024 src: 1
12:01:43.808 --P-> 05 64 12 C4 00 04 01 00 30 DD
12:01:43.808 C0 C3 02 32 01 07 01 D5 41 D3 64 71 01 8F 22
12:01:43.809 step: 15
12:01:43.809 - Read a single fragment response w/ sequence(0x03)
12:01:43.809 - Verify that the response is empty
12:01:43.809 - Verify that the IIN field does not contain bits IIN(NeedTime)
12:01:43.810 <-P-- 05 64 0A 44 01 00 00 04 67 88
12:01:43.810 C3 C3 81 00 00 D7 87
12:01:43.810 <-L-- master: 0 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0x44 length: 10 dest: 1 src: 1024
12:01:43.810 <-T-- fir: 1 fin: 1 seq: 3
12:01:43.810 <-A-- Response(0x81) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x03 IIN()
12:01:43.810 step: 16
12:01:43.810 - Generate several Binary Input Change Events
12:01:43.810 Updated BI 0: value=true, flags=81, timestamp=DNPTime(1586534498775)
12:01:43.811 Updated BI 0: value=false, flags=1, timestamp=DNPTime(1586534498775)
12:01:43.811 Updated BI 65535: value=true, flags=81, timestamp=DNPTime(1586534498776)
12:01:43.812 step: 17
12:01:43.812 - Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x04
12:01:43.812 - g2v3, All Objects
12:01:43.812 --A-> Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x04
12:01:43.812 g2v3, All Objects
12:01:43.812 --T-> fir: 1 fin: 1 seq: 0
12:01:43.813 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 11 dest: 1024 src: 1
12:01:43.813 --P-> 05 64 0B C4 00 04 01 00 CA 8A
12:01:43.813 C0 C4 01 02 03 06 20 69
12:01:43.818 steps: 18 to 21
12:01:43.818 - Read a single fragment response w/ sequence(0x04)
12:01:43.818 - Validate that a g51v1 precedes the g2v3 in each fragment of the response
12:01:43.818 - Validation that only g51v1 and g2v3 appears in the response
12:01:43.818 - Verify that flag behavior complies with Section 2, Note #5.
12:01:43.818 - Verify that an application layer confirmation is requested.
12:01:43.818 - Verify the device responds with all generated Binary Input events
12:01:43.818 - If the variation contains timestamps, verify that they are reasonable according to the resolution specified in the Device Profile
12:01:43.819 <-P-- 05 64 28 44 01 00 00 04 52 5F
12:01:43.819 C4 E4 81 00 00 33 01 07 01 D7 41 D3 64 71 01 02 BC F1
12:01:43.819 03 28 03 00 00 00 81 00 00 00 00 01 00 00 FF FF 93 85
12:01:43.819 81 01 00 AE 18
12:01:43.820 <-L-- master: 0 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0x44 length: 40 dest: 1 src: 1024
12:01:43.820 <-T-- fir: 1 fin: 1 seq: 4
12:01:43.822 <-A-- Response(0x81) fir: 1 fin: 1 con: 1 uns: 0 seq: 0x04 IIN()
12:01:43.822 g51v1, 1-Byte Count, count: 1
12:01:43.822 time: 1586534498775
12:01:43.822 g2v3, 2-Byte Count and Index, count: 3
12:01:43.822 [0] - flags: 0x81 cto: 0
12:01:43.822 [0] - flags: 0x01 cto: 0
12:01:43.822 [65535] - flags: 0x81 cto: 1
12:01:43.822 --A-> Confirm(0x00) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x04
12:01:43.822 --T-> fir: 1 fin: 1 seq: 0
12:01:43.823 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 8 dest: 1024 src: 1
12:01:43.823 --P-> 05 64 08 C4 00 04 01 00 9A 19
12:01:43.823 C0 C4 00 F9 A1
12:01:43.824 step: 22
12:01:43.824 - Generate several Binary Input Change Events
12:01:43.825 Updated BI 1024: value=false, flags=1, timestamp=DNPTime(1586534498789)
12:01:43.825 Updated BI 0: value=true, flags=81, timestamp=DNPTime(1586534498790)
12:01:43.825 Updated BI 0: value=false, flags=1, timestamp=DNPTime(1586534498790)
12:01:43.826 step: 23
12:01:43.826 - Wait for 5000 milliseconds
12:01:48.827 step: 24
12:01:48.827 - Delay Meas(0x17) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x05
12:01:48.827 --A-> Delay Meas(0x17) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x05
12:01:48.828 --T-> fir: 1 fin: 1 seq: 0
12:01:48.828 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 8 dest: 1024 src: 1
12:01:48.828 --P-> 05 64 08 C4 00 04 01 00 9A 19
12:01:48.828 C0 C5 17 46 3B
12:01:48.830 step: 25
12:01:48.830 - Read a single fragment response w/ sequence(0x05)
12:01:48.830 - Verify valid delay measurement response
12:01:48.830 - Verify that the IIN field contains IIN(NeedTime)
12:01:48.830 <-P-- 05 64 10 44 01 00 00 04 CD 4C
12:01:48.830 C5 C5 81 12 00 34 02 07 01 00 00 89 68
12:01:48.831 <-L-- master: 0 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0x44 length: 16 dest: 1 src: 1024
12:01:48.831 <-T-- fir: 1 fin: 1 seq: 5
12:01:48.832 <-A-- Response(0x81) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x05 IIN(NeedTime, Class1Events)
12:01:48.832 g52v2, 1-Byte Count, count: 1
12:01:48.832 delay: 0
12:01:48.833 step: 26
12:01:48.833 - Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x06
12:01:48.833 - g2v3, All Objects
12:01:48.833 --A-> Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x06
12:01:48.833 g2v3, All Objects
12:01:48.833 --T-> fir: 1 fin: 1 seq: 0
12:01:48.834 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 11 dest: 1024 src: 1
12:01:48.834 --P-> 05 64 0B C4 00 04 01 00 CA 8A
12:01:48.834 C0 C6 01 02 03 06 2C 2F
12:01:48.837 steps: 27 to 29
12:01:48.837 - Read a single fragment response w/ sequence(0x06)
12:01:48.837 - Validate that a g51v1 precedes the g2v3 in each fragment of the response
12:01:48.837 - Validation that only g51v1 and g2v3 appears in the response
12:01:48.837 - Verify that flag behavior complies with Section 2, Note #5.
12:01:48.837 - Verify that an application layer confirmation is requested.
12:01:48.837 - Verify the device responds with all generated Binary Input events
12:01:48.837 - If the variation contains timestamps, verify that they are reasonable according to the resolution specified in the Device Profile
12:01:48.838 <-P-- 05 64 28 44 01 00 00 04 52 5F
12:01:48.838 C6 E6 81 10 00 33 01 07 01 E5 41 D3 64 71 01 02 31 C7
12:01:48.838 03 28 03 00 00 04 01 00 00 00 00 81 01 00 00 00 2E D3
12:01:48.838 01 01 00 09 4D
12:01:48.838 <-L-- master: 0 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0x44 length: 40 dest: 1 src: 1024
12:01:48.839 <-T-- fir: 1 fin: 1 seq: 6
12:01:48.841 <-A-- Response(0x81) fir: 1 fin: 1 con: 1 uns: 0 seq: 0x06 IIN(NeedTime)
12:01:48.841 g51v1, 1-Byte Count, count: 1
12:01:48.841 time: 1586534498789
12:01:48.841 g2v3, 2-Byte Count and Index, count: 3
12:01:48.841 [1024] - flags: 0x01 cto: 0
12:01:48.841 [0] - flags: 0x81 cto: 1
12:01:48.841 [0] - flags: 0x01 cto: 1
12:01:48.841 step: 30
12:01:48.841 - Do not issue the application layer confirm
12:01:48.843 step: 31
12:01:48.843 - Write(0x02) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x07
12:01:48.843 - g50v1, 1-Byte Count, count: 1
12:01:48.843 - time: 1586534498773
12:01:48.843 --A-> Write(0x02) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x07
12:01:48.843 g50v1, 1-Byte Count, count: 1
12:01:48.843 time: 1586534498773
12:01:48.844 --T-> fir: 1 fin: 1 seq: 0
12:01:48.844 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 18 dest: 1024 src: 1
12:01:48.844 --P-> 05 64 12 C4 00 04 01 00 30 DD
12:01:48.844 C0 C7 02 32 01 07 01 D5 41 D3 64 71 01 98 46
12:01:48.846 step: 32
12:01:48.846 - Read a single fragment response w/ sequence(0x07)
12:01:48.846 - Verify that the response is empty
12:01:48.846 - Verify that the IIN field does not contain bits IIN(NeedTime)
12:01:48.846 <-P-- 05 64 0A 44 01 00 00 04 67 88
12:01:48.846 C7 C7 81 00 00 E4 D7
12:01:48.847 <-L-- master: 0 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0x44 length: 10 dest: 1 src: 1024
12:01:48.847 <-T-- fir: 1 fin: 1 seq: 7
12:01:48.847 <-A-- Response(0x81) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x07 IIN()
12:01:48.848 step: 33
12:01:48.848 - Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x08
12:01:48.848 - g2v3, All Objects
12:01:48.848 --A-> Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x08
12:01:48.848 g2v3, All Objects
12:01:48.849 --T-> fir: 1 fin: 1 seq: 0
12:01:48.849 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 11 dest: 1024 src: 1
12:01:48.850 --P-> 05 64 0B C4 00 04 01 00 CA 8A
12:01:48.850 C0 C8 01 02 03 06 71 B0
12:01:48.852 steps: 34 to 36
12:01:48.852 - Read a single fragment response w/ sequence(0x08)
12:01:48.852 - Validate that a g51v1 precedes the g2v3 in each fragment of the response
12:01:48.852 - Validation that only g51v1 and g2v3 appears in the response
12:01:48.852 - Verify that flag behavior complies with Section 2, Note #5.
12:01:48.852 - Verify that an application layer confirmation is requested.
12:01:48.852 - Verify the device responds with all generated Binary Input events
12:01:48.852 - If the variation contains timestamps, verify that they are reasonable according to the resolution specified in the Device Profile
12:01:48.853 <-P-- 05 64 28 44 01 00 00 04 52 5F
12:01:48.853 C8 E8 81 00 00 33 01 07 01 E5 41 D3 64 71 01 02 C4 99
12:01:48.853 03 28 03 00 00 04 01 00 00 00 00 81 01 00 00 00 2E D3
12:01:48.853 01 01 00 09 4D
12:01:48.853 <-L-- master: 0 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0x44 length: 40 dest: 1 src: 1024
12:01:48.854 <-T-- fir: 1 fin: 1 seq: 8
12:01:48.856 <-A-- Response(0x81) fir: 1 fin: 1 con: 1 uns: 0 seq: 0x08 IIN()
12:01:48.856 g51v1, 1-Byte Count, count: 1
12:01:48.856 time: 1586534498789
12:01:48.856 g2v3, 2-Byte Count and Index, count: 3
12:01:48.856 [1024] - flags: 0x01 cto: 0
12:01:48.856 [0] - flags: 0x81 cto: 1
12:01:48.856 [0] - flags: 0x01 cto: 1
12:01:48.856 --A-> Confirm(0x00) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x08
12:01:48.856 --T-> fir: 1 fin: 1 seq: 0
12:01:48.856 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 8 dest: 1024 src: 1
12:01:48.857 --P-> 05 64 08 C4 00 04 01 00 9A 19
12:01:48.857 C0 C8 00 A7 F9
12:01:48.858 step: 37
12:01:48.858 - Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x09
12:01:48.858 - g2v3, All Objects
12:01:48.859 --A-> Read(0x01) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x09
12:01:48.859 g2v3, All Objects
12:01:48.859 --T-> fir: 1 fin: 1 seq: 0
12:01:48.859 --L-> master: 1 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0xC4 length: 11 dest: 1024 src: 1
12:01:48.860 --P-> 05 64 0B C4 00 04 01 00 CA 8A
12:01:48.860 C0 C9 01 02 03 06 77 93
12:01:48.861 step: 38
12:01:48.861 - Read a single fragment response w/ sequence(0x09)
12:01:48.861 - Verify that the response is empty
12:01:48.861 <-P-- 05 64 0A 44 01 00 00 04 67 88
12:01:48.861 C9 C9 81 00 00 14 A9
12:01:48.862 <-L-- master: 0 pri: 1 fcb: 0 fcv: 0 func: UNCONFIRMED_USER_DATA(0x04) 0x44 length: 10 dest: 1 src: 1024
12:01:48.862 <-T-- fir: 1 fin: 1 seq: 9
12:01:48.862 <-A-- Response(0x81) fir: 1 fin: 1 con: 0 uns: 0 seq: 0x09 IIN()
12:01:48.862 Passed procedure: 8.15.2