disabling kernel messages (dmesg -n 1) is not realiable

[pmelange]

After the login_prompt of "Please press Enter to activate this console.", the ShellDriver writes dmesg -n 1 on the console to disable kernel messages on the console. But this does not always work. Sometimes the first couple characters are missing, sometime random characters are missing. Here are some examples from the log...

CONSOLE SerialLogger.ma:     SerialDriver(main) > dmesg -n 1␤␍␤
INFO         StepLogger:     → SerialDriver.expect(pattern=['root@[-\\w()]+:[^ ]+ ', 'Please press Enter to activate this console.', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]) 
CONSOLE SerialLogger.ma:      SerialDriver(main) < mesg -n 1␍␤
CONSOLE SerialLogger.ma:      SerialDriver(main) < -ash: mesg: not found␍␤

INFO         StepLogger:     → SerialDriver.expect(pattern=['root@[-\\w()]+:[^ ]+ ', 'Please press Enter to activate this console.', 'Password: ', <class 'pexpect.exceptions.TIMEOUT'>]) 
CONSOLE SerialLogger.ma:      SerialDriver(main) < ms- ␍␤
CONSOLE SerialLogger.ma:      SerialDriver(main) < -ash: ms-: not found␍␤

Perhaps some kind of check to see if dmesg -n 1 worked would be useful, which can be done by checking the contents of /proc/sys/kernel/printk. Or possibly it would be beneficial to add a sleep (user configurable with a default of 0 seconds) before running dmesg -n 1.

[Bastian-Krause]

Maybe experiment with the post_login_settle_time ShellDriver argument (also have a look at await_login_timeout)? If you're missing characters, maybe also experiment with the SerialDriver's txdelay.

There's not a lot else we can do at that stage because sending more commands increases the chances that Kernel messages disrupt the shell before we can silence it. In fact, dmesg -n 1 is sent before the run() injection happens to make it less fragile.

[pmelange]

post_login_settle_time happens after dmesg -n 1, so that doesn't help. And await_login_timeout is the maximum wait time until the login prompt, which happens before dmesg -n 1.

My current workaround is waiting until a far later kernel message for the login_prompt instead of Please press Enter to activate this console.. I will play around with the txdeay attribute to see how it affects everything.

Maybe it would be good to listen to the serial console for more kernel messages (lines starting with something like [ +\d+\.\d{6}]) and to retry dmesg -n 1 when more messages show up on the console. Such a check would go here.

labgrid/labgrid/driver/shelldriver.py

Lines 136 to 145 in 05a4eda

	if index == 0:
	if did_login and not did_silence_kernel:
	# Silence the kernel and wait for another prompt
	self.console.sendline("dmesg -n 1")
	did_silence_kernel = True
	else:
	# we got a prompt. no need for any further action to
	# activate this driver.
	self._status = 1
	break

[pmelange]

I have experimented with the txdelay attribute, and values of 0.01, 0.02, 0.03 and 0.05 don't work reliably.

But this patch works wonderfully without any need for txdelay.

diff --git a/labgrid/driver/shelldriver.py b/labgrid/driver/shelldriver.py
index 7d476f53..0ddeabd6 100644
--- a/labgrid/driver/shelldriver.py
+++ b/labgrid/driver/shelldriver.py
@@ -134,15 +134,19 @@ class ShellDriver(CommandMixin, Driver, CommandProtocol, FileTransferProtocol):
             )
 
             if index == 0:
-                if did_login and not did_silence_kernel:
+                while did_login and not did_silence_kernel:
                     # Silence the kernel and wait for another prompt
                     self.console.sendline("dmesg -n 1")
-                    did_silence_kernel = True
-                else:
-                    # we got a prompt. no need for any further action to
-                    # activate this driver.
-                    self._status = 1
-                    break
+                    index, _, _, _ = self.console.expect(["\w+: not found", 
+                                                          "\[\s*\d+.\d{6}\]", 
+                                                          TIMEOUT], 
+                                                         timeout=0.3)
+                    if index == 2:
+                        did_silence_kernel = True
+                # we got a prompt. no need for any further action to
+                # activate this driver.
+                self._status = 1
+                break
 
             elif index == 1:
                 # we need to login

[pmelange]

note: the expectation of \w+: not found works for sh and ash. An expectation of \w+: command not found would be needed for bash and zsh. I haven't tried other shells.

Therefore, the better expect seems to be

                    index, _, _, _ = self.console.expect(["\w+:( command)? not found", 
                                                          "\[\s*\d+.\d{6}\]", 
                                                          TIMEOUT], 
                                                         timeout=0.3)

[ynezz]

Sometimes the first couple characters are missing, sometime random characters are missing.

FYI #945