Compare logs for verification #30

mazimkhan · 2016-12-05T15:14:18Z

Compare logs for example verification in CI. Depends on ARMmbed/htrun#139
See format details here https://github.com/mazimkhan/htrun/blob/a6e5a04a60aecab408dfd2f6d62939cb69e3ae1c/README.md#testing-mbed-os-examples

mazimkhan · 2016-12-05T15:17:42Z

@sbutcher-arm @andresag01 Please review.

mazimkhan · 2016-12-12T17:38:31Z

@sbutcher-arm @andresag01

moved logs to tests directory.
Added missing DONE in tests/benchmark.log
Created tests/README.md

please review and merge.

andresag01

I think in general this is progressing in the right direction but I think there are a few issues:

The patterns should be tidied up according to the output. For instance, in benchmark matching a specific number of space characters may cause problems, and the hashing output may match a failed run.
I think the documentation gives too much detail in terms of example usages of htrun. I would prefer this to just explain the rationale of the .log files, how to use them and point to the htrun docs for more info.
There are a few typos in the README and is difficult to understand in places.

andresag01 · 2017-01-16T15:44:10Z

tests/authcrypt.log

+plaintext message: [0-9a-fA-F]*
+ciphertext: [0-9a-fA-F]*
+decrypted: [0-9a-fA-F]*
+DONE


There seems to be a lot of CRLF (\r\n) in these .log files. Is this necessary? If not, could we simple use \n like the rest of the project?

These are because the template is made out of a serial output. It is not hand made. We can remove \r for readability but that will require manual effort of making the logs readable.

andresag01 · 2017-01-16T15:45:43Z

tests/benchmark.log

+  ECDHE-Curve25519         :\s*\d+ ms/handshake
+  ECDH-secp384r1           :\s*\d+ ms/handshake
+  ECDH-secp256r1           :\s*\d+ ms/handshake
+  ECDH-Curve25519          :\s*\d+ ms/handshake


It seems that all these lines have a fixed number of spaces between the algorithm they are benchmarking and the : character. Perhaps it would be more robbust to use something like \s+?

We can do that if the code is suppose to change this space. Since it is fixed space we don't need to worry about it. Idea is to keep this approach simple and stupid and only put effort in regex for complex patterns.

Also one thing to bear in mind is that htrun first tries to compare a line character by character. In this case a line with special characters will also match. But if this comparison fails then htrun tries to use the line form the template as a regex. Hence if we remove any character from the template line (i.e. treating it as a regex) then we have to be careful of the characters in the line (regex). As characters like ()<>.*+\ are used as special meaning chars in the regex. They would then need to be escaped.

andresag01 · 2017-01-16T15:50:12Z

tests/README.md

+
+## How to create templated log
+
+The idea is to check that repeated execution of the examples produce same serial output. An example produces serial output when code contains ```printf``` statements. Serial output may change for ligitimate reasons like use of random data or data and time stamps. Thats why the log is converted to a template. This means that either the text/lines that differ in every execution are removed or they are converted into regular expressions. See the example below:


The first sentence says:

repeated execution of the examples produce same serial output

However, I thought that the idea is to check whether the output of an application matches an expected pattern.

Typo: ligitimate -> legitimate

I suggest: reasons like use of random data or data and time stamps -> reasons such as the use of random data or time stamps

I thing in the sentence Thats why the log should be That's why the log (notice the ')

andresag01 · 2017-01-16T15:59:48Z

tests/README.md

+
+```
+
+Please observe above that all the lines that have data that changes from execution to execution (on right) have been removed. It makes it possible htrun to compare these logs. htrun matches lines from the compare log (on left) one by one. It keeps on looking for a line until it matches. Once matched it moves on to match the next line. If it finds all lines from the compare log in the target serial output stream. Then it halts and passes the examples.


I suggest: Please observe above that all the lines that have data that changes from execution to execution (on right) have been removed. It makes it possible htrun to compare these logs -> Please observe above that all the lines that have data that changes from execution to execution (on right) have been removed enbling htrun to compare the logs

I suggest: Then it halts and passes the examples. -> Then it halts and the test passes.

andresag01 · 2017-01-16T16:05:28Z

tests/README.md

+
+Hello world!								Hello world!
+
+```


I think the rationale of the README is to provide some insight regarding the .log files. I think that having a short example is appropriate, however, I consider that the examples of htrun usage in this README are a bit too extensive and better suited to the htrun documentation itself. I suggest removing the tls-client example and simply leaving a fragment of the benchmark log comparison below (perhaps 4-5 lines). What are your thoughts @mazimkhan?

I would leave this example as it illustrates the one useful way of making a template log that is by removing random data.
We don't need to add anymore examples as these two cover the current approaches we take.

andresag01 · 2017-01-16T16:08:59Z

tests/authcrypt.log

@@ -0,0 +1,4 @@
+plaintext message: [0-9a-fA-F]*
+ciphertext: [0-9a-fA-F]*
+decrypted: [0-9a-fA-F]*


I think this regular expression is a little too simple. This will match something like:

plaintext message: ciphertext: decrypted:

Which is not correct output because there is no hash value.

Changed [0-9a-fA-F]* -> [0-9a-fA-F]+.

Sorry, my previous message was a bit misleading because I thought this was hashing instead of authcrypt. I still think bits of it do not need a complex regexp. For example the plaintext message and the decrypted message must be the same value (otherwise there is a serious problem) and is hardcoded in the example.

…ter regex

mazimkhan · 2017-01-16T17:47:26Z

@andresag01 Incorporated code review comments. Please review.

This review is no longer valid. Changes have been made to the PR since then.

andresag01 · 2017-01-30T10:17:45Z

@Azim: As discussed before, could you please remove the \r from the pattern files? Also, it seems that there are some issues with htrun in Linux.

…on linux host

mazimkhan · 2017-01-31T12:02:31Z

@andresag01 good find. Removed carriage return from the logs and it works for me now. Please try again.

andresag01 · 2017-01-31T15:16:23Z

@mazimkhan: Thanks for fixing the issues previously found. However, I am having difficulties trying to test these log files as mbedhtrun is not able to properly flash applications onto the target reliably in Linux. I get the following error:

[1485874580.84][COPY][INF] Waiting for mount point '/media/andama01/MBED' to be ready...
..............................cp: cannot create regular file '/media/andama01/MBED/benchmark.bin': No such file or directory
[1485874588.56][COPY][ERR] [ret=1] Command: ['cp', 'BUILD/K64F/GCC_ARM/benchmark.bin', '/media/andama01/MBED/benchmark.bin']

Furthermore, if I manually mount the device and then run mbedhtrun then the program works in some cases but it fails in some other cases with the following error:

[1485874744.02][HTST][INF] test suite run finished after 60.09 sec...
[1485874744.02][HTST][ERR] Expected output [DONE] not received in log.
[1485874744.03][CONN][INF] received special even '__host_test_finished' value='True', finishing
[1485874744.03][HTST][INF] CONN exited with code: 0
[1485874744.03][HTST][INF] Some events in queue
[1485874744.03][HTST][INF] stopped consuming events
[1485874744.03][HTST][INF] host test result(): None
[1485874744.03][HTST][WRN] missing __exit event from DUT
[1485874744.03][HTST][WRN] missing __exit_event_queue event from host test
[1485874744.03][HTST][ERR] missing __exit_event_queue event from host test and no result from host test, timeout...
[1485874744.03][HTST][INF] calling blocking teardown()
[1485874744.03][HTST][INF] teardown() finished
[1485874744.03][HTST][INF] {{result;timeout}}

mazimkhan · 2017-01-31T15:30:34Z

I believe you have some mounting issues. Can you also supply ‘-P 120’ option. 120 means 2 minutes. –P increases the timeout and may give enough time to htrun to remount the mbed device and run the test. From: Andres Amaya Garcia [mailto:[email protected]] Sent: 31 January 2017 15:16 To: ARMmbed/mbed-os-example-tls Cc: Azim Khan; Mention Subject: Re: [ARMmbed/mbed-os-example-tls] Campare logs for verification (#30) @mazimkhan<https://github.com/mazimkhan>: Thanks for fixing the issues previously found. However, I am having difficulties trying to test these log files as mbedhtrun is not able to properly flash applications onto the target reliably in Linux. I get the following error: [1485874580.84][COPY][INF] Waiting for mount point '/media/andama01/MBED' to be ready... ..............................cp: cannot create regular file '/media/andama01/MBED/benchmark.bin': No such file or directory [1485874588.56][COPY][ERR] [ret=1] Command: ['cp', 'BUILD/K64F/GCC_ARM/benchmark.bin', '/media/andama01/MBED/benchmark.bin'] Furthermore, if I manually mount the device and then run mbedhtrun then the program works in some cases but it fails in some other cases with the following error: [1485874744.02][HTST][INF] test suite run finished after 60.09 sec... [1485874744.02][HTST][ERR] Expected output [DONE] not received in log. [1485874744.03][CONN][INF] received special even '__host_test_finished' value='True', finishing [1485874744.03][HTST][INF] CONN exited with code: 0 [1485874744.03][HTST][INF] Some events in queue [1485874744.03][HTST][INF] stopped consuming events [1485874744.03][HTST][INF] host test result(): None [1485874744.03][HTST][WRN] missing __exit event from DUT [1485874744.03][HTST][WRN] missing __exit_event_queue event from host test [1485874744.03][HTST][ERR] missing __exit_event_queue event from host test and no result from host test, timeout... [1485874744.03][HTST][INF] calling blocking teardown() [1485874744.03][HTST][INF] teardown() finished [1485874744.03][HTST][INF] {{result;timeout}} — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub<#30 (comment)>, or mute the thread<https://github.com/notifications/unsubscribe-auth/AM5PEjHV_3oKeBnANfACE6SGzh4DUpIsks5rX1BIgaJpZM4LEVyH>. IMPORTANT NOTICE: The contents of this email and any attachments are confidential and may also be privileged. If you are not the intended recipient, please notify the sender immediately and do not disclose the contents to any other person, use it for any purpose, or store or copy the information in any medium. Thank you.

andresag01 · 2017-01-31T16:23:24Z

I ran the test for each of the examples and it seems to work as expected.

Campare logs for verification

1742dff

Mohammad Azim Khan added 3 commits December 12, 2016 17:14

Moved compare.log files to tests dir

35bca8a

Explained examples verification in tests/README.md

f43e411

Fixed tests\README.md markup

fd508b2

andresag01 previously requested changes Jan 16, 2017

View reviewed changes

Updated README.md with review suggestion and authcrypt.log with stric…

d357fa2

…ter regex

andresag01 added needs: review mbed TLS team labels Jan 24, 2017

andresag01 added needs: rework and removed needs: review labels Jan 30, 2017

Remove carriage return from example logs as that prevents comparison …

bf80693

…on linux host

andresag01 added needs: review and removed needs: rework labels Jan 31, 2017

andresag01 added needs: rework and removed needs: review labels Jan 31, 2017

andresag01 added ready for merge and removed needs: rework labels Jan 31, 2017

andresag01 merged commit ebc8e32 into ARMmbed:master Jan 31, 2017

simonbutcher changed the title ~~Campare logs for verification~~ Compare logs for verification Jan 31, 2017


		## How to create templated log

		The idea is to check that repeated execution of the examples produce same serial output. An example produces serial output when code contains ```printf``` statements. Serial output may change for ligitimate reasons like use of random data or data and time stamps. Thats why the log is converted to a template. This means that either the text/lines that differ in every execution are removed or they are converted into regular expressions. See the example below:


		```

		Please observe above that all the lines that have data that changes from execution to execution (on right) have been removed. It makes it possible htrun to compare these logs. htrun matches lines from the compare log (on left) one by one. It keeps on looking for a line until it matches. Once matched it moves on to match the next line. If it finds all lines from the compare log in the target serial output stream. Then it halts and passes the examples.

Compare logs for verification #30

Compare logs for verification #30

Uh oh!

Conversation

mazimkhan commented Dec 5, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mazimkhan commented Dec 5, 2016

Uh oh!

mazimkhan commented Dec 12, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

andresag01 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mazimkhan Jan 16, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

andresag01 Jan 16, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

andresag01 Jan 16, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mazimkhan commented Jan 16, 2017

Uh oh!

andresag01 commented Jan 30, 2017

Uh oh!

mazimkhan commented Jan 31, 2017

Uh oh!

andresag01 commented Jan 31, 2017

Uh oh!

mazimkhan commented Jan 31, 2017 via email

Uh oh!

andresag01 commented Jan 31, 2017

Uh oh!

Uh oh!

mazimkhan commented Dec 5, 2016 •

edited

Loading

mazimkhan commented Dec 12, 2016 •

edited

Loading

mazimkhan Jan 16, 2017 •

edited

Loading

andresag01 Jan 16, 2017 •

edited

Loading

andresag01 Jan 16, 2017 •

edited

Loading