action #16180
Updated by okurz about 4 years ago
As soon as #16166 issue is implemented, there is more room for improvement. If you look carefully at the logs, you will see how much valuable information are hidden inside of them:
The **debug** line
```
14:54:23.1988 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:27 called testapi::select_console
14:54:24.2461 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:28 called testapi::assert_script_run
14:54:27.8731 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:28 called testapi::assert_script_run
... etc ...
```
Since openQA spots the line number of the source file (`$test.pm`), we can now **which code path was touched** during the execution of the test.
The **<<<** line:
```
14:54:12.8437 15764 <<< testapi::assert_screen(mustmatch=['generic-desktop'], timeout=30)
14:54:15.1724 15764 <<< testapi::type_string(string='root', max_interval=250, wait_screen_changes=0)
14:54:56.7783 15764 <<< testapi::wait_serial(timeout=30, regexp=qr/(?^:JgRME-\d+-)/)
```
We see what openQA **requests** from the SUT to do.
The **>>>** line:
```
14:54:13.9297 15764 >>> testapi::_check_backend_response: found GNOME-20160523, similarity 1.00 @ 0/4
14:54:57.8247 15764 >>> testapi::wait_serial: (?^:JgRME-\d+-): ok
```
We see the **response** of the SUT, back to openQA.
Having these three identifiers in mind, you can improve the logging mechanism, like this:
```
Log for unzip tests/console/unzip.pm at 2017-01-20 14:54:14
27: select_console "root-console";
==================================
REQUEST: assert_screen(mustmatch=['tty2-selected','text-logged-in-root','text-login'], timeout=60)
REPLY : check_backend_response: found text-login-20140219, similarity 1.00 @ 0/0
REQUEST: type_string(string='root', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: assert_screen(mustmatch='password-prompt', timeout=30)
REPLY : check_backend_response: found password-prompt-20160405, similarity 1.00 @ 0/96
REQUEST: type_string(string='SECRET STRING', max_interval=100, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: send_key(key='ret')
REPLY : User Input (nothing to respond back)
REQUEST: assert_screen(mustmatch='text-logged-in-root', timeout=30)
REPLY : check_backend_response: found text-logged-in-root-20151204, similarity 1.00 @ 63/128
REQUEST: type_string(string='PS1=\'# \'', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: type_string(string='setterm -blank 0', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: type_string(string=' ; echo YpuUt-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: wait_serial(timeout=30, regexp=qr/(?^:YpuUt-\d+-)/)
REPLY : wait_serial: (?^:YpuUt-\d+-): ok
28: assert_script_run "mkdir -p /tmp/unzip-test/";
==================================================
REQUEST: type_string(string='mkdir -p /tmp/unzip-test/; echo Hb2bl-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: testapi::send_key(key='ret')
REPLY : User Input (nothing to respond back)
REQUEST: wait_serial(timeout=90, regexp='Hb2bl-\\d+-')
REPLY : wait_serial: Hb2bl-\d+-: ok
31: assert_script_run "wget --quiet " . data_url('console/test_unzip.zip') . " -O /tmp/unzip-test/archive.zip";
===============================================================================================================
REQUEST: type_string(string='wget --quiet http://10.0.2.2:20023/Vqm_u5zHrnPh24sA/data/console/test_unzip.zip -O /tmp/unzip-test/archive.zip; echo f15gk-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: testapi::send_key(key='ret')
REPLY : User Input (nothing to respond back)
REQUEST: wait_serial(timeout=90, regexp='f15gk-\\d+-')
REPLY : wait_serial: f15gk-\d+-: ok
32: assert_script_run "cd /tmp/unzip-test; unzip archive.zip";
==============================================================
REQUEST: type_string(string='cd /tmp/unzip-test; unzip archive.zip; echo Au17B-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: send_key(key='ret')
REPLY : User Input (nothing to respond back)
REQUEST: wait_serial(timeout=90, regexp='Au17B-\\d+-')
REPLY : wait_serial: Au17B-\d+-: ok
33: my $entries = script_output("ls -l /tmp/unzip-test/ | wc -l");
==================================================================
REQUEST: type_string(string='curl -f -v http://10.0.2.2:20023/Vqm_u5zHrnPh24sA/current_script > /tmp/scriptx6cVl.sh; echo iL~6F-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: send_key(key='ret')
REPLY : User Input (nothing to respond back)
REQUEST: wait_serial(timeout=90, regexp='iL~6F-\\d+-')
REPLY : wait_serial: iL~6F-\d+-: ok
REQUEST: type_string(string='clear', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: type_string(string=' ; echo JgRME-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: wait_serial(timeout=30, regexp=qr/(?^:JgRME-\d+-)/)
REPLY : wait_serial: (?^:JgRME-\d+-): ok
REQUEST: type_string(string='(/bin/bash -eox pipefail /tmp/scriptx6cVl.sh ; echo SCRIPT_FINISHEDx6cVl-$?-)| tee /dev/ttyS0', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: wait_serial(timeout=90, regexp='SCRIPT_FINISHEDx6cVl-\\d+-', record_output=1)
REPLY : wait_serial: SCRIPT_FINISHEDx6cVl-\d+-: ok
37: assert_script_run "wget --quiet " . data_url('console/checklist.md5') . " -O /tmp/unzip-test/checklist.md5";
================================================================================================================
REQUEST: type_string(string='wget --quiet http://10.0.2.2:20023/Vqm_u5zHrnPh24sA/data/console/checklist.md5 -O /tmp/unzip-test/checklist.md5; echo OS5Oh-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: send_key(key='ret')
REPLY : User Input (nothing to respond back)
REQUEST: wait_serial(timeout=90, regexp='OS5Oh-\\d+-')
REPLY : wait_serial: OS5Oh-\d+-: ok
38: assert_script_run "md5sum -c /tmp/unzip-test/checklist.md5";
================================================================
REQUEST: type_string(string='md5sum -c /tmp/unzip-test/checklist.md5; echo ZK27y-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: send_key(key='ret')
REPLY : User Input (nothing to respond back)
REQUEST: wait_serial(timeout=90, regexp='ZK27y-\\d+-')
REPLY : wait_serial: ZK27y-\d+-: ok
REQUEST: type_string(string='cd', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: type_string(string='clear', max_interval=250, wait_screen_changes=0)
REPLY : User Input (nothing to respond back)
REQUEST: assert_screen(mustmatch='cleared-console', timeout=30)
REPLY : check_backend_response: found cleared-console-autoyast-font-20141126, similarity 1.00 @ 0/1
```
Now, see the original log:
```
14:54:14.2858 15764 ||| starting unzip tests/console/unzip.pm at 2017-01-20 14:54:14
14:54:14.2861 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:27 called testapi::select_console
14:54:14.2861 15764 <<< testapi::select_console(testapi_console='root-console')
14:54:14.4961 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:27 called testapi::select_console
14:54:14.4962 15764 <<< testapi::assert_screen(mustmatch=[
'tty2-selected',
'text-logged-in-root',
'text-login'
], timeout=60)
14:54:14.5697 15789 MATCH(tty2-selected-20151201:1.00)
14:54:14.6466 15789 MATCH(tty2-selected-20160508:0.64)
14:54:14.6805 15789 MATCH(proxymode_text-logged-in-root-ssh-20161107:0.00)
14:54:14.7317 15789 MATCH(proxymode_text-logged-in-root-ssh-20161206:0.00)
14:54:14.7790 15789 MATCH(text-logged-in-root-20151204:0.00)
14:54:14.8261 15789 MATCH(text-logged-in-root-kgraft-20160727:0.00)
14:54:14.8739 15789 MATCH(text-logged-in-root-kgraft-20160728:0.00)
14:54:14.9202 15789 MATCH(text-logged-in-root-kgraft-ltp-20160727:0.00)
14:54:14.9749 15789 MATCH(text-logged-in-root-other-font-20151205:0.00)
14:54:15.0409 15789 MATCH(text-login-20140219:1.00)
14:54:15.0960 15789 MATCH(text-login-20160416:1.00)
14:54:15.1718 15764 >>> testapi::_check_backend_response: found text-login-20140219, similarity 1.00 @ 0/0
14:54:15.1723 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:27 called testapi::select_console
14:54:15.1724 15764 <<< testapi::type_string(string='root
', max_interval=250, wait_screen_changes=0)
14:54:15.5078 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:27 called testapi::select_console
14:54:15.5079 15764 <<< testapi::assert_screen(mustmatch='password-prompt', timeout=30)
14:54:15.5806 15789 MATCH(password-prompt-20141126:0.00)
14:54:15.6510 15789 MATCH(password-prompt-20150730:0.00)
14:54:15.7111 15789 MATCH(password-prompt-20160405:0.00)
14:54:15.7652 15789 MATCH(password-prompt-20160414:0.00)
14:54:15.8253 15789 MATCH(password-prompt-bsc965787-20160216:0.00)
14:54:15.8886 15789 MATCH(password-prompt-xterm-20150818:0.00)
14:54:15.8888 15789 no match 30
14:54:16.5187 15789 MATCH(password-prompt-20141126:0.60)
14:54:16.5267 15789 MATCH(password-prompt-20150730:0.00)
14:54:16.5542 15789 MATCH(password-prompt-20160405:1.00)
14:54:16.5632 15789 MATCH(password-prompt-20160414:0.00)
14:54:16.5709 15789 MATCH(password-prompt-bsc965787-20160216:0.95)
14:54:16.5781 15789 MATCH(password-prompt-xterm-20150818:0.00)
14:54:16.6466 15764 >>> testapi::_check_backend_response: found password-prompt-20160405, similarity 1.00 @ 0/96
14:54:16.6467 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:27 called testapi::select_console
14:54:16.6468 15764 <<< testapi::type_string(string='SECRET STRING', max_interval=100, wait_screen_changes=0)
14:54:18.1507 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:27 called testapi::select_console
14:54:18.1508 15764 <<< testapi::send_key(key='ret')
14:54:18.3516 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:27 called testapi::select_console
14:54:18.3517 15764 <<< testapi::assert_screen(mustmatch='text-logged-in-root', timeout=30)
14:54:18.4100 15789 MATCH(proxymode_text-logged-in-root-ssh-20161107:0.00)
14:54:18.4468 15789 MATCH(proxymode_text-logged-in-root-ssh-20161206:0.00)
14:54:18.4803 15789 MATCH(text-logged-in-root-20151204:0.00)
14:54:18.5241 15789 MATCH(text-logged-in-root-kgraft-20160727:0.00)
14:54:18.5785 15789 MATCH(text-logged-in-root-kgraft-20160728:0.00)
14:54:18.6137 15789 MATCH(text-logged-in-root-kgraft-ltp-20160727:0.00)
14:54:18.6491 15789 MATCH(text-logged-in-root-other-font-20151205:0.00)
14:54:18.6493 15789 no match 30
14:54:19.3628 15789 MATCH(proxymode_text-logged-in-root-ssh-20161107:0.00)
14:54:19.3690 15789 MATCH(proxymode_text-logged-in-root-ssh-20161206:0.00)
14:54:19.3739 15789 MATCH(text-logged-in-root-20151204:1.00)
14:54:19.3799 15789 MATCH(text-logged-in-root-kgraft-20160727:0.00)
14:54:19.3856 15789 MATCH(text-logged-in-root-kgraft-20160728:0.00)
14:54:19.3914 15789 MATCH(text-logged-in-root-kgraft-ltp-20160727:0.00)
14:54:19.3960 15789 MATCH(text-logged-in-root-other-font-20151205:0.82)
14:54:19.4417 15764 >>> testapi::_check_backend_response: found text-logged-in-root-20151204, similarity 1.00 @ 63/128
14:54:19.4417 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:27 called testapi::select_console
14:54:19.4418 15764 <<< testapi::type_string(string='PS1=\'# \'
', max_interval=250, wait_screen_changes=0)
14:54:20.0453 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:27 called testapi::select_console
14:54:20.0454 15764 <<< testapi::type_string(string='setterm -blank 0', max_interval=250, wait_screen_changes=0)
14:54:21.1175 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:27 called testapi::select_console
14:54:21.1176 15764 <<< testapi::type_string(string=' ; echo YpuUt-$?- > /dev/ttyS0
', max_interval=250, wait_screen_changes=0)
14:54:23.1988 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:27 called testapi::select_console
14:54:23.1990 15764 <<< testapi::wait_serial(timeout=30, regexp=qr/(?^:YpuUt-\d+-)/)
14:54:24.2461 15764 >>> testapi::wait_serial: (?^:YpuUt-\d+-): ok
14:54:24.2461 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:28 called testapi::assert_script_run
14:54:24.2462 15764 <<< testapi::script_run(name='mkdir -p /tmp/unzip-test/; echo Hb2bl-$?- > /dev/ttyS0', wait=0)
14:54:24.2462 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:28 called testapi::assert_script_run
14:54:24.2463 15764 <<< testapi::type_string(string='mkdir -p /tmp/unzip-test/; echo Hb2bl-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
14:54:27.8731 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:28 called testapi::assert_script_run
14:54:27.8732 15764 <<< testapi::send_key(key='ret')
14:54:28.0743 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:28 called testapi::assert_script_run
14:54:28.0744 15764 <<< testapi::wait_serial(timeout=90, regexp='Hb2bl-\\d+-')
14:54:29.1293 15764 >>> testapi::wait_serial: Hb2bl-\d+-: ok
14:54:29.1294 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:31 called testapi::assert_script_run
14:54:29.1295 15764 <<< testapi::script_run(name='wget --quiet http://10.0.2.2:20023/Vqm_u5zHrnPh24sA/data/console/test_unzip.zip -O /tmp/unzip-test/archive.zip; echo f15gk-$?- > /dev/ttyS0', wait=0)
14:54:29.1295 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:31 called testapi::assert_script_run
14:54:29.1295 15764 <<< testapi::type_string(string='wget --quiet http://10.0.2.2:20023/Vqm_u5zHrnPh24sA/data/console/test_unzip.zip -O /tmp/unzip-test/archive.zip; echo f15gk-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
14:54:38.4525 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:31 called testapi::assert_script_run
14:54:38.4526 15764 <<< testapi::send_key(key='ret')
14:54:38.6535 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:31 called testapi::assert_script_run
14:54:38.6536 15764 <<< testapi::wait_serial(timeout=90, regexp='f15gk-\\d+-')
14:54:39.7193 15764 >>> testapi::wait_serial: f15gk-\d+-: ok
14:54:39.7194 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:32 called testapi::assert_script_run
14:54:39.7195 15764 <<< testapi::script_run(name='cd /tmp/unzip-test; unzip archive.zip; echo Au17B-$?- > /dev/ttyS0', wait=0)
14:54:39.7195 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:32 called testapi::assert_script_run
14:54:39.7196 15764 <<< testapi::type_string(string='cd /tmp/unzip-test; unzip archive.zip; echo Au17B-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
14:54:44.1405 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:32 called testapi::assert_script_run
14:54:44.1406 15764 <<< testapi::send_key(key='ret')
14:54:44.3414 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:32 called testapi::assert_script_run
14:54:44.3414 15764 <<< testapi::wait_serial(timeout=90, regexp='Au17B-\\d+-')
14:54:45.3965 15764 >>> testapi::wait_serial: Au17B-\d+-: ok
14:54:45.3967 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:33 called testapi::script_output
14:54:45.3968 15764 <<< testapi::script_run(name='curl -f -v http://10.0.2.2:20023/Vqm_u5zHrnPh24sA/current_script > /tmp/scriptx6cVl.sh; echo iL~6F-$?- > /dev/ttyS0', wait=0)
14:54:45.3968 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:33 called testapi::script_output
14:54:45.3969 15764 <<< testapi::type_string(string='curl -f -v http://10.0.2.2:20023/Vqm_u5zHrnPh24sA/current_script > /tmp/scriptx6cVl.sh; echo iL~6F-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
14:54:53.1084 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:33 called testapi::script_output
14:54:53.1085 15764 <<< testapi::send_key(key='ret')
14:54:53.3093 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:33 called testapi::script_output
14:54:53.3094 15764 <<< testapi::wait_serial(timeout=90, regexp='iL~6F-\\d+-')
14:54:54.3653 15764 >>> testapi::wait_serial: iL~6F-\d+-: ok
14:54:54.3653 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:33 called testapi::script_output
14:54:54.3654 15764 <<< testapi::script_run(name='clear', wait=30)
14:54:54.3655 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:33 called testapi::script_output
14:54:54.3655 15764 <<< testapi::type_string(string='clear', max_interval=250, wait_screen_changes=0)
14:54:54.7010 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:33 called testapi::script_output
14:54:54.7011 15764 <<< testapi::type_string(string=' ; echo JgRME-$?- > /dev/ttyS0
', max_interval=250, wait_screen_changes=0)
14:54:56.7782 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:33 called testapi::script_output
14:54:56.7783 15764 <<< testapi::wait_serial(timeout=30, regexp=qr/(?^:JgRME-\d+-)/)
14:54:57.8247 15764 >>> testapi::wait_serial: (?^:JgRME-\d+-): ok
14:54:57.8248 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:33 called testapi::script_output
14:54:57.8249 15764 <<< testapi::type_string(string='(/bin/bash -eox pipefail /tmp/scriptx6cVl.sh ; echo SCRIPT_FINISHEDx6cVl-$?-)| tee /dev/ttyS0
', max_interval=250, wait_screen_changes=0)
14:55:04.1326 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:33 called testapi::script_output
14:55:04.1327 15764 <<< testapi::wait_serial(timeout=90, regexp='SCRIPT_FINISHEDx6cVl-\\d+-', record_output=1)
14:55:05.1826 15764 >>> testapi::wait_serial: SCRIPT_FINISHEDx6cVl-\d+-: ok
14:55:05.1827 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:37 called testapi::assert_script_run
14:55:05.1828 15764 <<< testapi::script_run(name='wget --quiet http://10.0.2.2:20023/Vqm_u5zHrnPh24sA/data/console/checklist.md5 -O /tmp/unzip-test/checklist.md5; echo OS5Oh-$?- > /dev/ttyS0', wait=0)
14:55:05.1828 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:37 called testapi::assert_script_run
14:55:05.1829 15764 <<< testapi::type_string(string='wget --quiet http://10.0.2.2:20023/Vqm_u5zHrnPh24sA/data/console/checklist.md5 -O /tmp/unzip-test/checklist.md5; echo OS5Oh-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
14:55:14.6033 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:37 called testapi::assert_script_run
14:55:14.6034 15764 <<< testapi::send_key(key='ret')
14:55:14.8042 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:37 called testapi::assert_script_run
14:55:14.8043 15764 <<< testapi::wait_serial(timeout=90, regexp='OS5Oh-\\d+-')
14:55:15.8781 15764 >>> testapi::wait_serial: OS5Oh-\d+-: ok
14:55:15.8782 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:38 called testapi::assert_script_run
14:55:15.8782 15764 <<< testapi::script_run(name='md5sum -c /tmp/unzip-test/checklist.md5; echo ZK27y-$?- > /dev/ttyS0', wait=0)
14:55:15.8782 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:38 called testapi::assert_script_run
14:55:15.8783 15764 <<< testapi::type_string(string='md5sum -c /tmp/unzip-test/checklist.md5; echo ZK27y-$?- > /dev/ttyS0', max_interval=250, wait_screen_changes=0)
14:55:20.4399 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:38 called testapi::assert_script_run
14:55:20.4400 15764 <<< testapi::send_key(key='ret')
14:55:20.6414 Debug: /var/lib/openqa/share/tests/sle/tests/console/unzip.pm:38 called testapi::assert_script_run
14:55:20.6415 15764 <<< testapi::wait_serial(timeout=90, regexp='ZK27y-\\d+-')
14:55:21.6875 15764 >>> testapi::wait_serial: ZK27y-\d+-: ok
14:55:21.6876 15764 <<< testapi::type_string(string='cd
', max_interval=250, wait_screen_changes=0)
14:55:21.8893 15764 <<< testapi::type_string(string='clear
', max_interval=250, wait_screen_changes=0)
14:55:22.2932 15764 <<< testapi::assert_screen(mustmatch='cleared-console', timeout=30)
14:55:22.3301 15789 MATCH(cleared-console-autoyast-font-20141126:0.21)
14:55:22.3612 15789 MATCH(consoletest_setup-20141125:0.21)
14:55:22.3613 15789 no match 30
14:55:23.3247 15789 MATCH(cleared-console-autoyast-font-20141126:1.00)
14:55:23.3531 15789 MATCH(consoletest_setup-20141125:1.00)
14:55:23.4008 15764 >>> testapi::_check_backend_response: found cleared-console-autoyast-font-20141126, similarity 1.00 @ 0/1
14:55:23.4011 15764 ||| finished unzip console at 2017-01-20 14:55:23 (69 s)
```
So, in the end, lot's of noise is removed, and valuable information are way more easily spotted. As a side-effect, more and more people will start looking at the logs and make themselves familiar with the internals of openQA.
More from #16184:
As soon as #16166 and #16180 are implemented, there is room for improving the the UI of openQA, especially for console-based tests. The current situation is that openQA takes a screenshot if:
* the API call requests a needle to match
* the tester wants to save a screenshot
* randomly (every 30 seconds? I am not really sure about the time-frame here)
I would like to propose to disable the feature of openQA to take randomly screenshots. Simply put, if there is not need to take a screenshot, then do NOT take one. There are console tests that require only 2 or 3 screenshots in order to match these equivalent needles, however in the end, you see 10 or even more. This is confusing and pointless because these frames were taken out of the blue.
What I would like to propose here is to take a screenshot per command. By command, is mean the line of the source code of the test that was touch at that point of time. For example:
Look for the code that was touch in the test (in that case I will show the unzip.pm)
```
27: select_console "root-console";
28: assert_script_run "mkdir -p /tmp/unzip-test/";
31: assert_script_run "wget --quiet " . data_url('console/test_unzip.zip') . " -O /tmp/unzip-test/archive.zip";
32: assert_script_run "cd /tmp/unzip-test; unzip archive.zip";
33: my $entries = script_output("ls -l /tmp/unzip-test/ | wc -l");
37: assert_script_run "wget --quiet " . data_url('console/checklist.md5') . " -O /tmp/unzip-test/checklist.md5";
38: assert_script_run "md5sum -c /tmp/unzip-test/checklist.md5";
```
So, in this particular example, openQA should show only 7 screenshots (meaning 1 screenshot per command). In that scenario, when the user clicks on one of them, then given that #16180 is implemented, openQA can show these logs right away. In that way, the whole review of a test is freaking quick and more enjoyable, since this is exactly the behavior that the user expects to see. In other words, people will enjoy debugging in openQA!
Furthermore, by implementing this feature, there will be no need for this extra screenshot (usually either green or red, **>_**) which checks for *wait_serial expected*. Actually, you can adapt this coloring-scheme functionality to these new screenshots (per command) I proposed, so if it passes: green, otherwise make it red as a whole unit.
Now, related to the other screenshots that openQA captures (I am referring to those required screenshots for needle-matching), I would like to hide them unless they missmatch. For example, matching a needle is part of an api-call. So, if we have screenshot per command (which includes none, or one or more API calls) there is not need to have extra ones, unless if a needle-matching has been failed.
So, less confusion, less disk space, more clarity, more fun :-)