connection was lost to loader node

[timtimb0t]

Argus:
https://argus.scylladb.com/tests/scylla-cluster-tests/f5da493d-5cb0-4f15-9d0f-687385d4b4b3

SCT wasnt able to connect to one of the loaders with the following error:

2025-04-19T04:54:43.162+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-4 !INFO | sshd[9602]: ssh_dispatch_run_fatal: Connection from 10.142.0.95 port 57000: Broken pipe [preauth]

That led to stress thread failure at step:

Traceback (most recent call last):
  File "/home/ubuntu/scylla-cluster-tests/sdcm/nemesis.py", line 5689, in wrapper
    result = method(*args[1:], **kwargs)
  File "/home/ubuntu/scylla-cluster-tests/sdcm/nemesis.py", line 1781, in disrupt_load_and_stream
    self._prepare_test_table(ks='keyspace1', table='standard1')
  File "/home/ubuntu/scylla-cluster-tests/sdcm/nemesis.py", line 2127, in _prepare_test_table
    cs_thread = self.tester.run_stress_thread(
  File "/home/ubuntu/scylla-cluster-tests/sdcm/tester.py", line 2024, in run_stress_thread
    return self.run_stress_cassandra_thread(**params)
  File "/home/ubuntu/scylla-cluster-tests/sdcm/tester.py", line 2070, in run_stress_cassandra_thread
    cs_thread = CassandraStressThread(loader_set=self.loaders,
  File "/home/ubuntu/scylla-cluster-tests/sdcm/stress_thread.py", line 78, in __init__
    super().__init__(loader_set=loader_set, stress_cmd=stress_cmd, timeout=timeout,
  File "/home/ubuntu/scylla-cluster-tests/sdcm/stress/base.py", line 59, in __init__
    RemoteDocker.pull_image(loader, self.docker_image_name)
  File "/home/ubuntu/scylla-cluster-tests/sdcm/utils/docker_remote.py", line 160, in pull_image
    docker_hub_login(remoter=node.remoter, use_sudo=node.is_docker)
  File "/home/ubuntu/scylla-cluster-tests/sdcm/utils/docker_utils.py", line 529, in docker_hub_login
    docker_info = remote_cmd("docker info", ignore_status=True)
  File "/home/ubuntu/scylla-cluster-tests/sdcm/remote/base.py", line 123, in sudo
    return self.run(cmd=cmd,
  File "/home/ubuntu/scylla-cluster-tests/sdcm/remote/remote_base.py", line 653, in run
    result = _run()
  File "/home/ubuntu/scylla-cluster-tests/sdcm/utils/decorators.py", line 72, in inner
    return func(*args, **kwargs)
  File "/home/ubuntu/scylla-cluster-tests/sdcm/remote/remote_base.py", line 646, in _run
    if self._run_on_retryable_exception(exc, new_session):
  File "/home/ubuntu/scylla-cluster-tests/sdcm/remote/remote_libssh_cmd_runner.py", line 78, in _run_on_retryable_exception
    raise RetryableNetworkException(str(exc), original=exc)
sdcm.remote.base.RetryableNetworkException: Failed to run a command due to exception!

Command: 'sudo docker info'

Stdout:



Stderr:



Exception:  File "/home/ubuntu/scylla-cluster-tests/sdcm/remote/libssh2_client/__init__.py", line 593, in run
    self.connect()
  File "/home/ubuntu/scylla-cluster-tests/sdcm/remote/libssh2_client/__init__.py", line 529, in connect
    raise ConnectTimeout(ex_msg) from exc

Failed to connect in 60 seconds, last error: (Timeout)

Not sure about the root cause of this failure

[soyacz]

something happened with load during disrupt_add_remove_mv - all load dropped to 0. Can you verify what happened to db/load. Maybe this is scylla issue (tablets are enabled and experimental_features: views-with-tablets are set).

[fruch]

seems like the loaders get disconnected from sct-runner:

2025-04-19T04:32:04.461+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | sshd[8728]: Received disconnect from 10.142.0.95 port 51456:11: end
2025-04-19T04:33:04.753+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | sshd[8728]: Disconnected from user scylla-test 10.142.0.95 port 51456
2025-04-19T04:35:45.298+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3  !WARNING | systemd-logind[1088]: Failed to abandon session scope, ignoring: Connection timed out
2025-04-19T04:36:28.741+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | sshd[8682]: pam_unix(sshd:session): session closed for user scylla-test

and then refuses to connect with:

2025-04-19T05:03:16.433+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3      !ERR | sshd[2921]: error: beginning MaxStartups throttling
2025-04-19T05:03:21.640+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | sshd[2921]: drop connection #60 from [10.142.0.95]:33422 on [10.142.0.187]:22 past MaxStartups
2025-04-19T05:03:23.254+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | sshd[2921]: exited MaxStartups throttling after 00:01:33, 5 connections dropped
2025-04-19T05:03:23.720+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3      !ERR | sshd[2921]: error: beginning MaxStartups throttling
2025-04-19T05:03:23.720+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | sshd[2921]: drop connection #60 from [10.142.0.95]:34814 on [10.142.0.187]:22 past MaxStartups
2025-04-19T05:03:24.145+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | sshd[2921]: exited MaxStartups throttling after 00:00:35, 3 connections dropped
2025-04-19T05:03:24.145+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3      !ERR | sshd[2921]: error: beginning MaxStartups throttling
2025-04-19T05:03:24.145+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | sshd[2921]: drop connection #60 from [10.142.0.95]:50806 on [10.142.0.187]:22 past MaxStartups
2025-04-19T05:03:24.145+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | sshd[2921]: exited MaxStartups throttling after 00:00:46, 4 connections dropped

and seems like the journald is crashing as well, and see only parts of the logs, and not all of it:

2025-04-19T06:25:17.895+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | snapd[684]: PC=0x5d91f2d542dd m=2 sigcode=0
2025-04-19T06:32:00.164+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | snapd[684]: goroutine 0 [idle]:
2025-04-19T06:34:08.435+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | snapd[684]: runtime.usleep()
2025-04-19T06:38:17.867+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | snapd[684]: 	runtime/sys_linux_amd64.s:149 +0x3d
2025-04-19T06:44:03.911+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | snapd[684]: runtime.sysmon()
2025-04-19T06:47:44.541+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | snapd[684]: 	runtime/proc.go:5067 +0xa5
2025-04-19T06:48:43.318+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3  !WARNING | systemd: systemd-journald.service: State 'stop-watchdog' timed out. Killing.
2025-04-19T06:48:44.863+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3   !NOTICE | systemd: systemd-journald.service: Killing process 240 (systemd-journal) with signal SIGKILL.
2025-04-19T06:48:44.863+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3  !WARNING | systemd: systemd-journald.service: Main process exited, code=killed, status=9/KILL
2025-04-19T06:48:44.863+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3  !WARNING | systemd: systemd-journald.service: Failed with result 'watchdog'.
2025-04-19T06:48:44.863+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3     !INFO | systemd: systemd-journald.service: Consumed 1.732s CPU time.
2025-04-19T06:48:44.863+00:00 longevity-large-partitions-200k-pks-loader-node-f5da493d-0-3  !WARNING | systemd: snapd.service: start operation timed out. Terminating

I would guess the loader is running out of memory

[fruch]

and yes seem like 4 of 5 loader are loosing memory quite rapidly:

[fruch]

@CodeLieutenant can you look into s-b, to see what can cause such a thing ( please rasise it in s-b)

@dimakr for awareness when going into stabilizing this test case, let's see if in other references of runs, we see this memory behaves like that, to see if we can help correlate the root cause of it.

[dimakr]

@CodeLieutenant can you look into s-b, to see what can cause such a thing ( please rasise it in s-b)
@dimakr for awareness when going into stabilizing this test case, let's see if in other references of runs, we see this memory behaves like that, to see if we can help correlate the root cause of it.

As we were adjusting longevity-large-partition-200k-pks-4days load profile in another task (where concurrency in stress_read_cmd s-b commnads is reduced by 10%), I had runs of this profile on both 2024.1.17 and master (Scylla version: 2025.2.0~dev-20250428.0cdcf82cd0ed) this week. In both cases the s-b image scylladb/scylla-bench:0.1.25 was used.
We didn't hit the ERROR: 10 attempts applied: Operation timed out for scylla_bench.test symptom on 2024.1.17 (I had 5 runs of the test in a row there this week). But constantly see it on master.

The problematic stress threads seems to be these 2 guys https://github.com/scylladb/scylla-cluster-tests/blob/50b3a82adcf8c0586dcd6acf10f2d8cd368420ac/test-cases/longevity/longevity-large-partition-200k_pks-4days.yaml#L32-34
They have the highest concurrency out of all threads in the config - 200+150 (180+135 in the adjusted config).
So if there are many requests that stay "in-flight" during retries, the memory consumption is increased (though I really doubt that multiple retries can cause 3-to-5 GiBs drops of available memory within 20 secs period).

If we compare how many read retries s-b performs:

• on master in the run these 2 'heavy' stress threads produce lots of retries within the time period when loaders are losing memory (one of loaders was lost there, similar to the issue in this ticket):

❯ egrep -l 'Mode:\s+read' loader-set-8677c9c8/longevity-large-partitions-200k-pks-loader-node-8677c9c8-0-*/scylla-bench* | xargs egrep -l 'Partition count:\s+1000'
loader-set-8677c9c8/longevity-large-partitions-200k-pks-loader-node-8677c9c8-0-4/scylla-bench-l4-e086106f-e4a5-4276-b956-7de0e286e6ac.log
❯ egrep -l 'Mode:\s+read' loader-set-8677c9c8/longevity-large-partitions-200k-pks-loader-node-8677c9c8-0-*/scylla-bench* | xargs egrep -l 'Partition count:\s+750'
loader-set-8677c9c8/longevity-large-partitions-200k-pks-loader-node-8677c9c8-0-5/scylla-bench-l5-3b65dd38-01de-4677-96e4-19b6069c00f3.log

❯ egrep 'SELECT.*retry: attemp' loader-set-8677c9c8/longevity-large-partitions-200k-pks-loader-node-8677c9c8-0-5/scylla-bench-l5-3b65dd38-01de-4677-96e4-19b6069c00f3.log | egrep '2025/04/29 14:[4-5][0-9]' | wc -l
4165
❯ egrep 'SELECT.*retry: attemp' loader-set-8677c9c8/longevity-large-partitions-200k-pks-loader-node-8677c9c8-0-4/scylla-bench-l4-e086106f-e4a5-4276-b956-7de0e286e6ac.log | egrep '2025/04/29 14:[4-5][0-9]' | wc -l
6294

• on the run against 2024.1.17 (e.g. this one) there is no observations of loaders losing memory and during the whole run only this number of retries is observed:

❯ egrep 'SELECT.*retry: attemp' loader-set-19f396ff/scylla-bench-l* | wc -l
566

[dimakr]

So summary for the previous comment - the same s-b image (v0.1.25) and the same stress workload causes memory loss on loaders on scylladb master, but is OK on the latest 2024.1 (2024.1.17).

[dimakr]

One more observation.
In loader system.log the following messages appear when we see available memory drops in Grafana for a loader.

Apr 29 14:43:47 longevity-large-partitions-200k-pks-loader-node-8677c9c8-0-5 kernel: virtio_balloon virtio2: Out of puff! Can't get 1 pages
Apr 29 14:43:49 longevity-large-partitions-200k-pks-loader-node-8677c9c8-0-5 kernel: virtio_balloon virtio2: Out of puff! Can't get 1 pages
Apr 29 14:43:49 longevity-large-partitions-200k-pks-loader-node-8677c9c8-0-5 kernel: virtio_balloon virtio2: Out of puff! Can't get 1 pages
Apr 29 14:43:49 longevity-large-partitions-200k-pks-loader-node-8677c9c8-0-5 kernel: virtio_balloon virtio2: Out of puff! Can't get 1 pages

It basically means that the host is reclaiming memory from guest VM and at some points the guest OS kernel cannot provide even a single page of memory back to host.

So if host started to reclaim memory from VMs around the time we have massive retries in scylla-bench threads, does it mean that memory drops are self-inflicted by loaders behavior?
I.e. heavy scylla-bench load makes the loader VM very active. And this increased activity might trigger the resource balancing mechanisms of hypervisor, one of which is memory ballooning?
So maybe the memory pressure on VMs is from both sides - heavy stress load consumes memory inside VM and host reclaims memory from outside, thus we are seeing big drops of available memory (3-to-5 Gibs, sometimes 10Gibs within 20 secs).