Hi Stefan,
Thank you for showing me that post. It has more or less confirmed an idea I had as to why it may not be working. I had suspected it may be lava matching to the previous prompt instead of the current, which at the time seemed both plausible and yet ridiculous, but it is the best explanation for overlapping commands. The particular delay I found most effective until now wasn't as crazy as 100ms, but several delays for commands at approximately 5ms each.
There is not much I can do to change the test or device configuration for the prompt, as my device simply uses '#' as the prompt for commands. There is something I have noticed though, that seems unique to telnet, which is that there is some kind of an "echo", where there is an empty prompt after every command execution. minicom does not have this, nor does ssh. Iirc, this can be disabled in interactive tests. Is there a way to disable this for regular tests or in general? I am not sure it will be effective at solving the issue, but it is worth a shot.
If you want to see logs, I will paste the part of the plain log here where the failure happens: - {"dt": "2024-03-24T20:37:41.827319", "lvl": "debug", "msg": "Setting prompt string to ['# ']"} - {"dt": "2024-03-24T20:37:41.827995", "lvl": "debug", "msg": "Forcing a shell prompt, looking for ['# ']"} - {"dt": "2024-03-24T20:37:41.828663", "lvl": "input", "msg": "\n"} - {"dt": "2024-03-24T20:37:41.879484", "lvl": "target", "msg": "# "} - {"dt": "2024-03-24T20:37:41.880437", "lvl": "debug", "msg": "expect-shell-connection: Wait for prompt ['# '] (timeout 00:05:00)"} - {"dt": "2024-03-24T20:37:41.881144", "lvl": "debug", "msg": "Waiting using forced prompt support (timeout 00:02:30)"} - {"dt": "2024-03-24T20:37:41.881966", "lvl": "target", "msg": ""} - {"dt": "2024-03-24T20:37:41.901778", "lvl": "target", "msg": ""} - {"dt": "2024-03-24T20:37:41.902572", "lvl": "target", "msg": "# "} - {"dt": "2024-03-24T20:37:41.903598", "lvl": "debug", "msg": "end: 2.4 expect-shell-connection (duration 00:00:00) [common]"} - {"dt": "2024-03-24T20:37:41.904420", "lvl": "debug", "msg": "start: 2.5 overlay-unpack (timeout 00:03:38) [common]"} - {"dt": "2024-03-24T20:37:41.905174", "lvl": "input", "msg": "rm overlay-1.4.2.5.tar.gz\n"} - {"dt": "2024-03-24T20:37:42.006073", "lvl": "target", "msg": "# rm overlay-1.4.2.5.tar.gz"} - {"dt": "2024-03-24T20:37:42.008397", "lvl": "debug", "msg": "Sending with 100 millisecond of delay"} - {"dt": "2024-03-24T20:37:42.009156", "lvl": "input", "msg": "cd / ; tar -C /tmp/ -xzf /data/wgetcurl.tar.gz ; cd /tmp/ ; sleep 2\n"} - {"dt": "2024-03-24T20:37:52.131475", "lvl": "target", "msg": "cd / ; tar -C /tmp/ -xzf /data/wgetcurl.tar.gz ; cd /tmp/ ; sleep 2"} - {"dt": "2024-03-24T20:37:52.233013", "lvl": "target", "msg": "rm overlay-1.4.2.5.tar.gz"} - {"dt": "2024-03-24T20:37:52.234357", "lvl": "target", "msg": "rm overlay-1.4.2.5.tar.gz"} - {"dt": "2024-03-24T20:37:52.235107", "lvl": "target", "msg": "crm: can't remove 'overlay-1.4.2.5.tar.gz': No such file or directory"} - {"dt": "2024-03-24T20:37:52.236086", "lvl": "target", "msg": "# "} - {"dt": "2024-03-24T20:37:52.236652", "lvl": "target", "msg": "# d / ; tar -C /tmp/ -xzf /data/wgetcurl.tar.gz ; cd /tmp/ ; sleep 2"} - {"dt": "2024-03-24T20:37:52.237197", "lvl": "target", "msg": "cd / ; tar -C /tmp/ -xzf /data/wgetcurl.tar.gz ; cd /tmp/ ; sleep 2"} - {"dt": "2024-03-24T20:37:52.238553", "lvl": "debug", "msg": "Sending with 100 millisecond of delay"} - {"dt": "2024-03-24T20:37:52.239190", "lvl": "input", "msg": "/tmp/wgetcurl/wget http://10.60.2.209/tmp/505/compress-overlay-mubx369r/overlay-1.4.2.5.tar.gz%... - {"dt": "2024-03-24T20:38:06.419274", "lvl": "target", "msg": "/tmp/wgetcurl/wget http://10.60.2.209/tmp/505/compress-overlay-mubx369r/overlay-1.4.2.5.tar.gz%... - {"dt": "2024-03-24T20:38:06.522664", "lvl": "debug", "msg": "Sending with 100 millisecond of delay"} - {"dt": "2024-03-24T20:38:06.523485", "lvl": "input", "msg": "tar -C /tmp -xzf overlay-1.4.2.5.tar.gz\n"} - {"dt": "2024-03-24T20:38:12.435400", "lvl": "target", "msg": "tar -C /tmp -xzf overlay-1.4.2.5.tar.gz"} - {"dt": "2024-03-24T20:38:12.536924", "lvl": "target", "msg": "/tmp/wgetcurl/wget http://10.6# "} - {"dt": "2024-03-24T20:38:12.537783", "lvl": "target", "msg": "# 0.2.209/tmp/505/compress-overlay-mubx369r/overlay-1.4.2.5.tar.gz"} - {"dt": "2024-03-24T20:38:12.538566", "lvl": "target", "msg": "/t[ 70.070000] ttyS ttyS0: 1 input overrun(s)"} - {"dt": "2024-03-24T20:38:12.539238", "lvl": "target", "msg": "mp/wgetcurl/wget http:/10.60ay-1.4.2.5.tar.gz"} - {"dt": "2024-03-24T20:38:12.539887", "lvl": "target", "msg": "ta--2024-03-24 20:37:47-- ftp://http//10.60ay-1.4.2.5.tar.gz"} - {"dt": "2024-03-24T20:38:12.540534", "lvl": "target", "msg": " => '10.60ay-1.4.2.5.tar.gz'"} - {"dt": "2024-03-24T20:38:12.541168", "lvl": "target", "msg": "Resolving http... r -C /tmp -xzf overlay-1.4.2.5.tar.gz"} - {"dt": "2024-03-24T20:38:12.541804", "lvl": "target", "msg": "tar -C /tmp -xzf overlay-1.4.2.5.tar.gz"} - {"dt": "2024-03-24T20:38:12.542495", "lvl": "target", "msg": ""} - {"dt": "2024-03-24T20:38:12.543693", "lvl": "debug", "msg": "end: 2.5 overlay-unpack (duration 00:00:31) [common]"} - {"dt": "2024-03-24T20:38:12.544612", "lvl": "debug", "msg": "start: 2.6 export-device-env (timeout 00:03:08) [common]"} - {"dt": "2024-03-24T20:38:12.545549", "lvl": "debug", "msg": "end: 2.6 export-device-env (duration 00:00:00) [common]"} - {"dt": "2024-03-24T20:38:12.546567", "lvl": "info", "msg": "end: 2 minimal-boot (duration 00:01:52) [common]"} - {"dt": "2024-03-24T20:38:12.547476", "lvl": "info", "msg": "start: 3 lava-test-retry (timeout 00:05:00) [common]"} - {"dt": "2024-03-24T20:38:12.548381", "lvl": "debug", "msg": "start: 3.1 lava-test-shell (timeout 00:05:00) [common]"} - {"dt": "2024-03-24T20:38:12.549129", "lvl": "debug", "msg": "Using namespace: common"} - {"dt": "2024-03-24T20:38:12.549894", "lvl": "input", "msg": "#\n"} - {"dt": "2024-03-24T20:38:12.650937", "lvl": "target", "msg": "#"} - {"dt": "2024-03-24T20:38:12.652301", "lvl": "debug", "msg": "lava-test-shell: Wait for prompt ['# '] (timeout 00:05:00)"} - {"dt": "2024-03-24T20:38:12.653278", "lvl": "debug", "msg": "Using /tmp/lava-505"} - {"dt": "2024-03-24T20:38:12.653913", "lvl": "input", "msg": "export SHELL=/bin/sh\n"} - {"dt": "2024-03-24T20:38:12.755166", "lvl": "target", "msg": "export SHELL=/bin/sh"} - {"dt": "2024-03-24T20:38:12.756527", "lvl": "target", "msg": "#"} - {"dt": "2024-03-24T20:38:12.757552", "lvl": "target", "msg": "#"} - {"dt": "2024-03-24T20:38:12.758430", "lvl": "target", "msg": ""} - {"dt": "2024-03-24T20:38:12.759326", "lvl": "target", "msg": "export SHELL=/bin/sh"} - {"dt": "2024-03-24T20:38:12.785528", "lvl": "target", "msg": "export SHELL=/bin/sh"} - {"dt": "2024-03-24T20:38:12.786460", "lvl": "target", "msg": ""} - {"dt": "2024-03-24T20:38:16.893918", "lvl": "target", "msg": "failed: Temporary failure in name resolution."} - {"dt": "2024-03-24T20:38:16.894892", "lvl": "target", "msg": "wget: unable to resolve host address 'http'"} - {"dt": "2024-03-24T20:38:16.958057", "lvl": "target", "msg": "# "} - {"dt": "2024-03-24T20:38:16.959242", "lvl": "input", "msg": ". /tmp/lava-505/environment\n"} - {"dt": "2024-03-24T20:38:17.060570", "lvl": "target", "msg": "# tar -C /tmp -xzf o. /tmp/lava-505/environment"} - {"dt": "2024-03-24T20:38:17.061874", "lvl": "input", "msg": "/tmp/lava-505/bin/lava-test-runner /tmp/lava-505/0\n"} - {"dt": "2024-03-24T20:38:17.163565", "lvl": "target", "msg": "/tmp/lava-505/bin/lava-test-runner /tmp/lava-505/0"} - {"dt": "2024-03-24T20:38:17.164670", "lvl": "info", "msg": "Test shell timeout: 10s (minimum of the action and connection timeout)"} - {"dt": "2024-03-24T20:38:17.167644", "lvl": "target", "msg": "verlay-1.4.2.5.tar.gz"} - {"dt": "2024-03-24T20:38:17.168419", "lvl": "target", "msg": ". /tmp/lava-505/environmenttar: can't open 'overlay-1.4.2.5.tar.gz': No such file or directory"} - {"dt": "2024-03-24T20:38:17.169109", "lvl": "target", "msg": "# "} - {"dt": "2024-03-24T20:38:17.169753", "lvl": "target", "msg": "# #"} - {"dt": "2024-03-24T20:38:17.170442", "lvl": "target", "msg": "# "} - {"dt": "2024-03-24T20:38:17.171078", "lvl": "target", "msg": "# export SHELL=/bin/sh"} - {"dt": "2024-03-24T20:38:17.171719", "lvl": "target", "msg": "# "} - {"dt": "2024-03-24T20:38:17.172355", "lvl": "target", "msg": "# "} - {"dt": "2024-03-24T20:38:17.172989", "lvl": "target", "msg": ". /tmp/la/tmp/lava-505/bin/lava-test-runner /tmp/lava-505/0va-505/environment"} - {"dt": "2024-03-24T20:38:17.173633", "lvl": "target", "msg": "-sh: .: can't open '/tmp/lava-505/environment': No such file or directory"} - {"dt": "2024-03-24T20:38:17.174326", "lvl": "target", "msg": "# "} - {"dt": "2024-03-24T20:38:17.174951", "lvl": "target", "msg": "# "} - {"dt": "2024-03-24T20:38:17.207624", "lvl": "target", "msg": "/tmp/lava-505/bin/lava-test-runner /tmp/lava-505/0"} - {"dt": "2024-03-24T20:38:17.223874", "lvl": "target", "msg": "-sh: /tmp/lava-505/bin/lava-test-runner: not found"} - {"dt": "2024-03-24T20:38:17.239721", "lvl": "target", "msg": "# "}
After that I cancelled the test as I didn't want or need to wait for it to time out, since intervention would be required to get the test to finish, and I am just trying to get it working. As of this reply that is the latest test I have run. If there is anything else needed to help diagnose the issue and come up with a solution, please let me know so I can do my best to provide more information.
Best regards, Michael