Removing the escape sequence from the console outputs!

[Anushree-Mathur]

Testcases fail as the output is having escape sequence in it which is not expected to be there.Removing this escape sequence fixes almost 2000+ testcases.
Signed-off-by: Anushree Mathur [email protected]

[Anushree-Mathur]

efore applying the patch i tried to print the outputs in between and found out the escape sequence issue.Many testcases were getting failed, 1 of the example is as follows:

[stdout] NEW NONEMPTY LIST []
[stdout]
[stdout] CONT in the read_until_last_line_matches
[stdout] Last login: Fri Jan  3 07:46:25 from 192.168.122.1
[stdout] ^[[?2004h[root@localhost ~]#
[stdout]
[stdout] nonempty lines in until last line matches ['Last login: Fri Jan  3 07:46:25 from 192.168.122.1', '\x1b[?2004h[root@localhost ~]# ']
[stdout]
[stdout] Nonempty lines are true in read_until_last ['Last login: Fri Jan  3 07:46:25 from 192.168.122.1', '\x1b[?2004h[root@localhost ~]# ']
[stdout] 
[stdout] \x1b[?2004h[root@localhost ~]#

 (1/3) io-github-autotest-qemu.unattended_install.import.import.default_install.aio_native: STARTED
 (1/3) io-github-autotest-qemu.unattended_install.import.import.default_install.aio_native: PASS (244.46 s)
 (2/3) type_specific.io-github-autotest-libvirt.virsh.migrate.there_and_back_with_numa.with_numa_only.with_mem_hotplug.with_cpu_hotplug.with_hotplug.hotplug_after_migration.compat_migration.non_compat_migration.with_postcopy: STARTED
 (2/3) type_specific.io-github-autotest-libvirt.virsh.migrate.there_and_back_with_numa.with_numa_only.with_mem_hotplug.with_cpu_hotplug.with_hotplug.hotplug_after_migration.compat_migration.non_compat_migration.with_postcopy: ERROR: Login timeout expired    (output: 'exceeded 240 s timeout') (672.89 s)
 (3/3) io-github-autotest-libvirt.remove_guest.without_disk: STARTED
 (3/3) io-github-autotest-libvirt.remove_guest.without_disk: PASS (5.10 s)

After applying the patch, testcases are getting passed:

[stdout] Nonempty lines are true in read_until_last ['Last login: Fri Jan  3 09:04:36 from 192.168.122.1', '\x1b[?2004h[root@localhost ~]# ']
[stdout]
[stdout] [root@localhost ~]#

Last element of the list gets used after removing the escape sequence. This is necessary to check for the the proper login.

 (1/3) io-github-autotest-qemu.unattended_install.import.import.default_install.aio_native: STARTED
 (1/3) io-github-autotest-qemu.unattended_install.import.import.default_install.aio_native: PASS (230.22 s)
 (2/3) type_specific.io-github-autotest-libvirt.virsh.migrate.there_and_back_with_numa.with_numa_only.with_mem_hotplug.with_cpu_hotplug.with_hotplug.hotplug_after_migration.compat_migration.non_compat_migration.with_postcopy: STARTED
 (2/3) type_specific.io-github-autotest-libvirt.virsh.migrate.there_and_back_with_numa.with_numa_only.with_mem_hotplug.with_cpu_hotplug.with_hotplug.hotplug_after_migration.compat_migration.non_compat_migration.with_postcopy: PASS (626.06 s)
 (3/3) io-github-autotest-libvirt.remove_guest.without_disk: STARTED
 (3/3) io-github-autotest-libvirt.remove_guest.without_disk: PASS (5.01 s)

[ldoktor]

Hello @Anushree-Mathur, this change makes sense to me as in get_last_non_empty_line we do expect console output which might be corrupted by console codes. My only concern is whether we shouldn't strip the full output as the current version might result in "" output (when last nonempty line contains only escape code, it'll be identified as non-empty and then stripped).

I think I need an extra pair of eyes on this as it might affect the behaviour @smitterl or @pevogam can you please take a look at this?

[Anushree-Mathur]

Hello @ldoktor, thanks alot for taking time and reviewing this commit! The much I have understood, IMO the output will surely be something with the escape sequence but if it is only containing escape sequence and stripping this comes as empty ouput, maybe that was expected? The output that is coming in the console and the way it is getting read, those are different! So it will take the output only until the last nonempty output that is correct according to the console but the escape code gets added in a way it gets read. Please correct me if i am wrong.

Thanks in advance!

[ldoktor]

Hello @ldoktor, thanks alot for taking time and reviewing this commit! The much I have understood, IMO the output will surely be something with the escape sequence but if it is only containing escape sequence and stripping this comes as empty ouput, maybe that was expected? The output that is coming in the console and the way it is getting read, those are different! So it will take the output only until the last nonempty output that is correct according to the console but the escape code gets added in a way it gets read. Please correct me if i am wrong.

Thanks in advance!

I'm talking about situation like this foo\nbar\n\x1b[33;1m. With your modification it returns "" while originally it returned "\x1b[33;1m". I think it'd be better to strip the input so it becomes foo\nbar\n and only "bar" gets returned.

[pevogam]

Hi, I will be able to test and review this towards the end of the week, I hope this is ok and thanks for the contribution!

[ldoktor]

Thanks @pevogam. Btw it'd be nice to include a selftest. One example I tried was to create a file:

foo
bar
[user@computer ~ ]$ 
^[[0;31m^[[0m

And then run

>>> import aexpect
>>> a=aexpect.ShellSession("bash -c 'cat /tmp/test; sleep 10'")
>>> a.read_up_to_prompt()
'foo\nbar\n[user@computer ~ ]$ \n\x1b[0;31m\x1b[0m\n'
>>> a.read_up_to_prompt()
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/home/medic/Work/Projekty/avocado/aexpect/aexpect/client.py", line 1186, in read_up_to_prompt
    return self.read_until_last_line_matches([self.prompt], timeout,
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/medic/Work/Projekty/avocado/aexpect/aexpect/client.py", line 1002, in read_until_last_line_matches
    return self.read_until_output_matches(patterns,
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/medic/Work/Projekty/avocado/aexpect/aexpect/client.py", line 940, in read_until_output_matches
    raise ExpectProcessTerminatedError(patterns, self.get_status(),
aexpect.exceptions.ExpectProcessTerminatedError: Process terminated while looking for pattern '[\\#\\$]\\s*$'    (status: 0,    output: '')

Also while looking at this we might want to improve the status from cmd_status_output to also remove the potential extra output (especially for serial consoles that occasionally spits some escape codes).

[Anushree-Mathur]

Thank you so much @pevogam @ldoktor for your time! I am getting your point now @ldoktor, I am also looking into this, will get back to you on this by tomorrow. Thank you for the clarification. But still I have 1 doubt, in my case the output is getting stripped at first and then it is returning only the last element of the list after removing the escape sequence!

For example:
Following is the input
Last login: Fri Jan 3 07:46:25 from 192.168.122.1
^[[?2004h[root@localhost ~]#

It is getting stripped as a list as ['Last login: Fri Jan 3 07:46:25 from 192.168.122.1', '\x1b[?2004h[root@localhost ~]# ']

Then the value that the code is returning is the last output without the escape sequence that is [root@localhost ~]#
Other value also exist but i was printing only the last element of the list!

This function itself means that it is returning only the last element of the list. I apologize for multiple questions, but just reclarifying the things! Thanks in advance for your time!

[ldoktor]

I'm not sure I follow, can you please elaborate a bit more? The function you're modifying is inside a filter function _get_last_nonempty_line which is used by read_until_last_line_matches to only match the latest output from Tail process and is often used to read up to prompt (which should be the last non-empty line). Thank you for noticing that when the output contains extra characters (eg. when executing echo -n whatever) the last line might contain these control characters (eg. \x1b[?2004h) which we can and probably should remove by astring.strip_console_codes.

My proposal was about another potential situation, where the console spits additional content after the last line which would again contain only control characters (eg. Last login: Fri Jan 3 07:46:25 from 192.168.122.1\n[root@localhost ~]# \n\x1b[?2004h). In such case the current code returns "\x1b[?2004g", your code returns "" and I'm proposing it should ignore those lines as well and return last non-empty one "[root@localhost ~]# ".

[Anushree-Mathur]

Hi @ldoktor, now I totally got your point. Before I got confused that maybe my code is doing something wrong! I can edit the code in such a way that it checks whether a last output contains only escape characters or control characters and if it is empty then it will return as the output as [root@localhost ~]#, as it is in my case! I will work on this potential situation as you have mentioned in the comment. Thank you so much for the reclarification.