ubuntu-kernel-tests

Bug #2057886
Comment #0

Comment 0 for bug 2057886

Revision history for this message

Po-Hsu Lin (cypressyew) wrote on 2024-03-14:

Issue found exclusively on GCP "g1-small" instance with the following kernels:
  * X 4.4.0-252.286 lowlatency (cycle
  * X-hwe 4.15.0-223.235~16.04.1 lowlatency (s2024.02.05 cycle)
  * F 5.4.0-175.195 lowlatency (2024.03.04 cycle)

It looks like it's not 100% reproducible as it has passed with
* B-lowlatency 4.15.0-223.235 (s2024.02.05 cycle)
* F 5.4.0-174.193 lowlatency (s2024.02.05 cycle)

When this happens, test will be interrupted:
14:49:12 INFO | START ubuntu_stress_smoke_test.prio-inv ubuntu_stress_smoke_test.prio-inv timestamp=1710254952 timeout=2100 localtime=Mar 12 14:49:12 14:49:12 DEBUG| Persistent state client._record_indent now set to 2
14:49:12 DEBUG| Persistent state client.unexpected_reboot now set to ('ubuntu_stress_smoke_test.prio-inv', 'ubuntu_stress_smoke_test.prio-inv')
14:49:12 DEBUG| Waiting for pid 12620 for 2100 seconds
14:49:12 DEBUG| Running '/home/ubuntu/autotest/client/tests/ubuntu_stress_smoke_test/ubuntu_stress_single_smoke_test.sh prio-inv'
14:49:12 DEBUG| [stdout] Free memory: 1217 MB
14:49:12 DEBUG| [stdout] Memory used: 705 MB
14:49:12 DEBUG| [stdout] Using cgroup version 1
14:49:12 ERROR| [stderr] /home/ubuntu/autotest/client/tests/ubuntu_stress_smoke_test/ubuntu_stress_single_smoke_test.sh: line 32: [: too many arguments
14:49:12 DEBUG| [stdout]
14:49:12 DEBUG| [stdout] Machine Configuration
14:49:12 DEBUG| [stdout] Physical Pages: 431526
14:49:12 DEBUG| [stdout] Pages available: 311706
14:49:12 DEBUG| [stdout] Page Size: 4096
14:49:12 DEBUG| [stdout] Zswap enabled: Y
14:49:12 DEBUG| [stdout]
14:49:12 DEBUG| [stdout] Free memory:
14:49:12 DEBUG| [stdout] total used free shared buff/cache available
14:49:12 DEBUG| [stdout] Mem: 1726104 134820 1246824 11344 344460 1328560
14:49:12 DEBUG| [stdout] Swap: 1048572 512 1048060
14:49:12 DEBUG| [stdout]
14:49:12 DEBUG| [stdout] Number of CPUs: 1
14:49:12 DEBUG| [stdout] Number of CPUs Online: 1
14:49:12 DEBUG| [stdout]
14:49:12 DEBUG| [stdout] Maximum bogo ops: 3000
14:49:12 DEBUG| [stdout]
14:49:12 DEBUG| [stdout] prio-inv STARTING
(system disconnects here)
rsync: connection unexpectedly closed (0 bytes received so far) [Receiver]
rsync error: unexplained error (code 255) at io.c(231) [Receiver=3.2.7]

Here is the collected console log:
Mar 14 07:42:15 f-l-ll-5-4-g1sml-u-stress-smk-test systemd[1]: Finished GCE Workload Certificate refresh.^M
Mar 14 07:42:24 f-l-ll-5-4-g1sml-u-stress-smk-test systemd[1]: Started Session 7 of user ubuntu.^M
Mar 14 07:46:04 f-l-ll-5-4-g1sml-u-stress-smk-test PackageKit: daemon quit^M
Mar 14 07:46:04 f-l-ll-5-4-g1sml-u-stress-smk-test systemd[1]: packagekit.service: Succeeded.^M
Mar 14 07:48:28 [ 1847.057112] INFO: task jbd2/sda1-8:280 blocked for more than 123 seconds.^M
[ 1847.067198] Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1847.073489] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1847.081740] INFO: task kworker/u2:1:17304 blocked for more than 123 seconds.^M
[ 1850.064409] Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1850.070514] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1973.046096] INFO: task jbd2/sda1-8:280 blocked for more than 249 seconds.^M
[ 1973.061945] Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1976.044464] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1976.053184] INFO: task systemd-journal:355 blocked for more than 128 seconds.^M
[ 1976.060673] Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1976.066844] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1982.044713] INFO: task rs:main Q:Reg:719 blocked for more than 134 seconds.^M
[ 1982.052278] Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1982.058451] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1982.066722] INFO: task kworker/u2:1:17304 blocked for more than 258 seconds.^M
[ 1985.063183] Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1988.047580] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 2114.030688] INFO: task jbd2/sda1-8:280 blocked for more than 390 seconds.^M
[ 2114.038876] Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 2114.045149] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 2114.053295] INFO: task systemd-journal:355 blocked for more than 266 seconds.^M
[ 2117.036368] Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 2117.042507] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 2117.050832] INFO: task rs:main Q:Reg:719 blocked for more than 269 seconds.^M
[ 2120.034201] Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 2120.040333] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 2120.048505] INFO: task kworker/u2:1:17304 blocked for more than 396 seconds.^M
[ 2123.035654] Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 2123.041809] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M

It looks like it's not 100% reproducible as it has passed with
  * B-lowlatency 4.15.0-223.235 (s2024.02.05 cycle)
  * F 5.4.0-174.193 lowlatency (s2024.02.05 cycle)

When this happens, test will be interrupted:
14:49:12 INFO |     START    ubuntu_stress_smoke_test.prio-inv    ubuntu_stress_smoke_test.prio-inv    timestamp=1710254952    timeout=2100    localtime=Mar 12 14:49:12     14:49:12 DEBUG| Persistent state client._record_indent now set to 2
14:49:12 DEBUG| Persistent state client.unexpected_reboot now set to ('ubuntu_stress_smoke_test.prio-inv', 'ubuntu_stress_smoke_test.prio-inv')
14:49:12 DEBUG| Waiting for pid 12620 for 2100 seconds
14:49:12 DEBUG| Running '/home/ubuntu/autotest/client/tests/ubuntu_stress_smoke_test/ubuntu_stress_single_smoke_test.sh prio-inv'
14:49:12 DEBUG| [stdout] Free memory: 1217 MB
14:49:12 DEBUG| [stdout] Memory used: 705 MB
14:49:12 DEBUG| [stdout] Using cgroup version 1 
14:49:12 ERROR| [stderr] /home/ubuntu/autotest/client/tests/ubuntu_stress_smoke_test/ubuntu_stress_single_smoke_test.sh: line 32: [: too many arguments
14:49:12 DEBUG| [stdout]  
14:49:12 DEBUG| [stdout] Machine Configuration
14:49:12 DEBUG| [stdout] Physical Pages:  431526
14:49:12 DEBUG| [stdout] Pages available: 311706
14:49:12 DEBUG| [stdout] Page Size:       4096
14:49:12 DEBUG| [stdout] Zswap enabled:   Y
14:49:12 DEBUG| [stdout]  
14:49:12 DEBUG| [stdout] Free memory:
14:49:12 DEBUG| [stdout]               total        used        free      shared  buff/cache   available
14:49:12 DEBUG| [stdout] Mem:        1726104      134820     1246824       11344      344460     1328560
14:49:12 DEBUG| [stdout] Swap:       1048572         512     1048060
14:49:12 DEBUG| [stdout]  
14:49:12 DEBUG| [stdout] Number of CPUs: 1
14:49:12 DEBUG| [stdout] Number of CPUs Online: 1
14:49:12 DEBUG| [stdout] 
14:49:12 DEBUG| [stdout] Maximum bogo ops: 3000 
14:49:12 DEBUG| [stdout]  
14:49:12 DEBUG| [stdout] prio-inv STARTING
(system disconnects here)
rsync: connection unexpectedly closed (0 bytes received so far) [Receiver] 
rsync error: unexplained error (code 255) at io.c(231) [Receiver=3.2.7]

Here is the collected console log:
Mar 14 07:42:15 f-l-ll-5-4-g1sml-u-stress-smk-test systemd[1]: Finished GCE Workload Certificate refresh.^M
Mar 14 07:42:24 f-l-ll-5-4-g1sml-u-stress-smk-test systemd[1]: Started Session 7 of user ubuntu.^M
Mar 14 07:46:04 f-l-ll-5-4-g1sml-u-stress-smk-test PackageKit: daemon quit^M
Mar 14 07:46:04 f-l-ll-5-4-g1sml-u-stress-smk-test systemd[1]: packagekit.service: Succeeded.^M
Mar 14 07:48:28 [ 1847.057112] INFO: task jbd2/sda1-8:280 blocked for more than 123 seconds.^M
[ 1847.067198]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1847.073489] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1847.081740] INFO: task kworker/u2:1:17304 blocked for more than 123 seconds.^M
[ 1850.064409]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1850.070514] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1973.046096] INFO: task jbd2/sda1-8:280 blocked for more than 249 seconds.^M
[ 1973.061945]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1976.044464] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1976.053184] INFO: task systemd-journal:355 blocked for more than 128 seconds.^M
[ 1976.060673]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1976.066844] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1982.044713] INFO: task rs:main Q:Reg:719 blocked for more than 134 seconds.^M
[ 1982.052278]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1982.058451] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 1982.066722] INFO: task kworker/u2:1:17304 blocked for more than 258 seconds.^M
[ 1985.063183]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 1988.047580] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 2114.030688] INFO: task jbd2/sda1-8:280 blocked for more than 390 seconds.^M
[ 2114.038876]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 2114.045149] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 2114.053295] INFO: task systemd-journal:355 blocked for more than 266 seconds.^M
[ 2117.036368]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 2117.042507] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 2117.050832] INFO: task rs:main Q:Reg:719 blocked for more than 269 seconds.^M
[ 2120.034201]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 2120.040333] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M
[ 2120.048505] INFO: task kworker/u2:1:17304 blocked for more than 396 seconds.^M
[ 2123.035654]       Not tainted 5.4.0-175-lowlatency #195-Ubuntu^M
[ 2123.041809] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.^M