diff --git a/CHANGELOG.md b/CHANGELOG.md index f02e58a3..b2042dba 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -198,6 +198,38 @@ All notable changes to PyBNF are documented below. This project adheres to says what it has not bisected. ### Fixed +- **When the workers cannot be started, the message says what went wrong and what to try + instead (#618).** A multi-machine run whose workers failed to start stopped with + `Failed to start the dask-ssh cluster (dask-ssh exited with code 1)` and, on the cluster this + was reported from, nothing else. The real cause was that the login to the other machines had + failed, and no part of the message said so, named a cause, or named a way of running that + needs no login. Stopping was right — carrying on with fewer machines than were asked for + wastes the whole run — but a hard stop makes that message the entirety of what the user gets. + It was empty because the half of dask's output that explains the failure was discarded twice + over. `dask ssh` prints its own account of a refused login — the node it was connecting to, + and the exception paramiko raised — to **stdout**, and lets only the traceback fall to stderr; + PyBNF captured stderr and sent stdout to `DEVNULL`. And dask ends a failed bring-up with + `os._exit(1)`, which does not flush Python's buffers, so its few hundred bytes of stdout never + reached the 8 KB that would have forced a write to the file. Measured against dask 2026.7.1 on + a login that fails: **0** of dask's own lines survived; **15** survive now that PyBNF captures + both streams into one file and runs dask unbuffered. + The message now quotes what dask said, and says so plainly when there was nothing to quote + rather than falling back to "Check the cluster log directory" without naming a directory. The + traceback frames are folded out of it — a failed login writes one traceback per node per + retry, three retries each, and the sentences that say what happened are buried in dask's and + paramiko's own source: **137** captured lines became **32**, losing none of those sentences. + The log still keeps every line. + When the output reads as a refused credential — "Authentication failed", "No authentication + methods available", an encrypted key, a host key that did not match — the message says the + login is the likely cause and says what PyBNF logs in with: paramiko, which can offer a public + key or a typed password and nothing else, so a cluster that authenticates its nodes to each + other by host-based or Kerberos (GSSAPI) SSH refuses it however it is configured, `ssh` from + the same shell succeeds anyway, and `ssh-keygen` cannot help. A machine that could not be + reached at all is deliberately *not* answered that way. Whatever the cause, the message names + both ways of running on several machines that need no login: `cluster_type = slurm-srun` + (#614), which starts the workers inside the allocation SLURM already granted, and a + `scheduler_file` naming a cluster that is already up. `docs/cluster.rst` and + `docs/troubleshooting.rst` now say the same. - **The cluster tests now notice when an outside program is renamed (#619).** The tests for starting a cluster checked that PyBNF built a particular command, against a copy of that command written into the test file. Nothing checked that the command could be run. When diff --git a/docs/cluster.rst b/docs/cluster.rst index 6734e9a2..baca6c11 100644 --- a/docs/cluster.rst +++ b/docs/cluster.rst @@ -70,6 +70,8 @@ If you use one of the first two, the login must succeed without a password promp * It raises ``AuthenticationException`` while plain ``ssh`` to the same node succeeds: your cluster authenticates its nodes to each other by a method paramiko cannot use -- most often host-based or Kerberos (GSSAPI) SSH. **Creating SSH keys cannot fix this**, because the cluster is not asking for a key. Use `Starting workers without SSH`_. * It asks for a password, or fails in the same way plain ``ssh`` does: this is the case SSH keys do fix. Create a key pair with ``ssh-keygen`` (documented in many places, such as `here `__) and append the public half to ``~/.ssh/authorized_keys``. Where the nodes share your home directory, that covers all of them at once. Then run the check above again. +**What a failed login looks like.** PyBNF stops about ten seconds into the run rather than carrying on with fewer machines than you asked for, and quotes what ``dask ssh`` said -- including dask's own account of the failure, which names the node it was connecting to and the exception paramiko raised. When that output reads as a refused credential, the message says the login is the likely cause, says what PyBNF logs in with, and names the two ways of running that need no login at all. The same output is in the log file, tracebacks and all. + If SSH cannot be made to work for some other reason, `Starting workers without SSH`_ and `Manual configuration with Dask`_ both avoid it entirely. .. _srun: diff --git a/docs/troubleshooting.rst b/docs/troubleshooting.rst index cf46a3d4..0966ab8c 100644 --- a/docs/troubleshooting.rst +++ b/docs/troubleshooting.rst @@ -209,6 +209,26 @@ of the run). It is still an estimated parameter, so it is still counted in ``k`` as an ordinary free parameter and reported alongside the model parameters. +Could not start the workers on the other machines +------------------------------------------------- + +``dask ssh``, which PyBNF runs to start the workers of a multi-machine run, exited before any +worker started, so the run stops about ten seconds in. Everything ``dask ssh`` said is quoted +in the message and repeated in the log file. + +The most common cause is the login itself. ``dask ssh`` does not run your ``ssh`` command: it +logs in with the paramiko library, which can offer a public key or a typed password and nothing +else. A cluster whose nodes authenticate to each other by host-based or Kerberos (GSSAPI) SSH +therefore refuses it however you configure it -- on a machine where ``ssh othernode hostname`` +from the same shell succeeds -- and creating SSH keys cannot fix it, because the cluster is not +asking for a key. :ref:`Which ways of starting a run log in to other machines ` gives +a one-line test of the login PyBNF actually makes. + +Two ways of running on several machines need no login at all, and neither is affected: +:ref:`starting the workers with srun ` (``-t slurm-srun``), inside the allocation SLURM +already granted, and :ref:`starting the scheduler and workers yourself ` and giving +PyBNF the scheduler file with ``-s``. + PyBNF has encountered a fatal error ----------------------------------- This error occurs when the scheduler loses connection with the cluster. The simulation data is generally backed up and the simulation can be resumed from the point it exited using the -r flag 'pybnf -c .conf -r'. diff --git a/pybnf/cluster.py b/pybnf/cluster.py index af0f74aa..a73bc9c0 100644 --- a/pybnf/cluster.py +++ b/pybnf/cluster.py @@ -14,7 +14,9 @@ with paramiko, which offers only public-key and password authentication -- it has no host-based support and dask never enables its GSSAPI support -- so on such a cluster the login fails no matter what the user configures, and no amount of ``ssh-keygen`` helps. See -docs/adr/0122 for the full argument. +docs/adr/0122 for the full argument. When that login is what fails, the SSH launcher says +so, quotes what ``dask ssh`` said, and names both ways of running that need no login +(#618) -- the failure ends the run, so the message is the whole of what the user gets. Both launchers size their default worker pool from what the *job* was granted rather than from how big the machine is, and record which number they used and where it came from @@ -26,7 +28,7 @@ from importlib.metadata import entry_points from importlib.util import find_spec -from subprocess import run, TimeoutExpired, Popen, PIPE, CalledProcessError, DEVNULL, STDOUT +from subprocess import run, TimeoutExpired, Popen, PIPE, CalledProcessError, STDOUT from tempfile import TemporaryFile import json @@ -97,6 +99,25 @@ DASK_CLI = [sys.executable, '-m', 'dask'] +# What a failed SSH bring-up says when the *login* is what failed (#618). The words can +# come from either half of what PyBNF captures: dask prints its own account of the failure +# ("SSH reported this exception: ") and lets paramiko's traceback +# fall to stderr, and both now land in one file. This is the vocabulary of a refused +# credential only -- "Authentication failed", "No authentication methods available", an +# encrypted key (PasswordRequiredException), a host key that did not match. Deliberately +# not dask's own "SSH connection error" heading, which it prints for a machine that could +# not be reached at all just as readily: a network failure is a different problem, and +# answering it with advice about keys and passwords would send the user the wrong way. +SSH_LOGIN_FAILURE_RE = re.compile( + r'authentication|SSHException|permission denied|publickey|password|host ?key', + flags=re.IGNORECASE) + +# Terminal colour codes, which dask wraps its failure lines in. They have to come out +# before that text is quoted into a log file or an error message, where they would +# otherwise appear as literal escape characters. +ANSI_ESCAPE_RE = re.compile(r'\x1b\[[0-9;]*[A-Za-z]') + + def check_dask_subcommand(subcommand): """ Confirm that ``dask `` can be run by this interpreter, before running it. @@ -355,6 +376,9 @@ def setup_cluster(node_string, out_dir, parallel_count=None): nodes, divided evenly among them. If None, one worker per CPU the job was granted on a node (``cpus_per_node``) :return: subprocess.Popen + :raises PybnfError: if ``dask ssh`` has already exited when the bring-up wait is + over -- quoting everything it said, naming the login as the likely cause when + it looks like one, and naming the ways of running that need no login (#618) """ # Ask before launching, so a dask that cannot do this reads as a configuration # error rather than as a FileNotFoundError traceback from Popen (#615). @@ -389,26 +413,153 @@ def setup_cluster(node_string, out_dir, parallel_count=None): % (n_per_node, len(nodes), parallel_count)) dask_ssh_cmd = [*DASK_CLI, 'ssh', *nodes, '--log-directory', out_dir, '--nworkers', str(n_per_node), '--nthreads', '1'] - # Capture stderr to a temp file rather than a PIPE: dask ssh stays - # running for the whole fit, and an undrained PIPE would deadlock once - # its buffer fills. A regular file lets us surface an early bring-up - # failure below without that risk. - dask_ssh_err = TemporaryFile() - dask_ssh_proc = Popen(dask_ssh_cmd, stdout=DEVNULL, stderr=dask_ssh_err) + # Capture what dask ssh says to a temp file rather than to a PIPE: dask ssh stays + # running for the whole fit, and an undrained PIPE would deadlock once its buffer + # fills. A regular file lets us surface an early bring-up failure below without + # that risk. + # + # stdout is captured too rather than discarded (#618). When a login fails, dask + # prints its own account of it -- which node it was connecting to, and the + # exception paramiko raised -- with ``print``, and only the traceback falls to + # stderr. Sending stdout to DEVNULL therefore threw away the half of the output + # that names the cause, which is how a refused login could reach the user as a + # bare exit code with nothing else attached. Keeping the stream costs nothing for + # the rest of a healthy run: ``--log-directory`` above makes dask redirect each + # remote command's output into a file on its own node, so the SSH channels carry + # almost nothing back. + # + # ``PYTHONUNBUFFERED`` is what makes capturing stdout worth anything. dask ends a + # failed bring-up with ``os._exit(1)``, which does not flush Python's buffers, and + # stdout writing to a file is block-buffered -- so its account of the failure, a + # few hundred bytes short of the buffer's 8 KB, is discarded at exit and never + # reaches the file at all. Measured against dask 2026.7.1 on a login that fails: + # 0 of dask's own lines survive without this, all 15 with it. + dask_ssh_out = TemporaryFile() + dask_ssh_proc = Popen(dask_ssh_cmd, stdout=dask_ssh_out, stderr=STDOUT, + env=dict(os.environ, PYTHONUNBUFFERED='1')) time.sleep(10) # If dask ssh has already exited, the cluster never came up. Surface the # failure here instead of letting it resurface later as an opaque dask # Client connection error. returncode = dask_ssh_proc.poll() if returncode is not None: - dask_ssh_err.seek(0) - err_text = dask_ssh_err.read().decode('UTF-8', errors='replace').strip() - dask_ssh_err.close() - logger.error(f'dask ssh exited with code {returncode} during cluster bring-up. stderr:\n{err_text}') - raise PybnfError('Failed to start the dask ssh cluster (dask ssh exited with code {}). {}'.format(returncode, (f'Details:\n{err_text}') if err_text - else 'Check the cluster log directory for details.')) + output = Cluster.captured_text(dask_ssh_out) + dask_ssh_out.close() + # The log keeps every line, including the traceback frames; the message keeps + # what a user can act on. + logger.error('dask ssh exited with code %s during cluster bring-up. Output:\n%s' + % (returncode, output if output else '(it produced none)')) + raise PybnfError( + 'Could not start the workers on the other machines: dask ssh exited with code ' + '%s during cluster bring-up.\n%s' + % (returncode, + ('This is what it said:\n%s' % Cluster.fold_traceback_frames(output)) + if output else + ('It produced no output at all. Anything the nodes themselves wrote is ' + 'in %s on each of them.' % out_dir)), + hint=Cluster.ssh_bringup_hints(output)) return dask_ssh_proc + @staticmethod + def captured_text(handle): + """ + Read back everything a launched process wrote to its capture file, as plain text. + + Colour escapes are removed: dask colours its own failure lines, and those bytes + would otherwise reach a log file and an error message as literal characters. + + :param handle: The open binary file the process was given as its output + :return: the captured text, or '' if nothing was captured or it cannot be read + :rtype: str + """ + try: + handle.seek(0) + text = handle.read().decode('UTF-8', errors='replace') + except (OSError, ValueError): + return '' + return ANSI_ESCAPE_RE.sub('', text).strip() + + @staticmethod + def fold_traceback_frames(text, lines=40): + """ + The same output with Python traceback frames folded away, for an error message. + + What ``dask ssh`` writes when a login fails is mostly traceback: one per node per + retry, three retries each, every one of them a dozen frames of dask's and + paramiko's own source. Quoted whole, the sentences that say what happened -- dask's + "SSH reported this exception: ...", and the exception line each traceback ends with + -- are buried in code the user did not write and cannot act on, and are the first + thing a length limit throws away. Folding the frames left 32 lines of a measured + 137, and lost none of the sentences. + + Each traceback is recognized by its header and ends at the first line that is not + indented, which is the exception itself; that line is kept, the frames between are + dropped. The full text still goes to the log. + + :param text: The captured output + :type text: str + :param lines: Number of trailing lines to keep after folding + :type lines: int + :return: the output without traceback frames, at most ``lines`` lines + :rtype: str + """ + kept = [] + in_frames = False + for line in text.splitlines(): + if line.startswith('Traceback (most recent call last)'): + in_frames = True + continue + if in_frames: + if not line.strip() or line[:1].isspace(): + continue + in_frames = False + kept.append(line) + return '\n'.join(kept[-lines:]) + + @staticmethod + def ssh_bringup_hints(output): + """ + What to suggest to a user whose SSH bring-up failed (#618). + + Two things a bare exit code does not tell them. First, whether the login is the + problem: on the cluster this was reported from it was, and no part of the message + said so. A login failure is worth naming outright because the obvious remedy -- + creating SSH keys -- fixes only one of its causes, and because ``ssh`` succeeding + from the same shell makes the failure look impossible (``dask ssh`` does not run + ``ssh``; it logs in with paramiko, which offers a public key or a password and + nothing else). + + Second, that a failed login is not the end of the run: two of the ways PyBNF can + use several machines never log in anywhere, and both remain open. They are named + whatever the cause, since anything that stops ``dask ssh`` leaves them as the ways + forward. + + :param output: What dask ssh wrote before exiting + :type output: str + :return: suggested remedies, most specific first + :rtype: list + """ + hints = [] + if SSH_LOGIN_FAILURE_RE.search(output or ''): + hints.append( + 'This looks like a failed login. PyBNF starts the workers with `dask ssh`, ' + 'which does not run your `ssh` command: it logs in with the paramiko ' + 'library, which can offer a public key or a typed password and nothing ' + 'else. A cluster whose nodes authenticate to each other by host-based or ' + 'Kerberos (GSSAPI) SSH refuses that login however you configure it, and ' + 'creating SSH keys does not help -- the cluster is not asking for a key. ' + '`ssh OTHERNODE hostname` succeeding proves nothing here; the "Running on ' + 'a cluster" documentation gives a one-line test of the login PyBNF makes.') + hints.append( + 'Two ways of running on several machines need no login at all. On a SLURM ' + 'cluster, cluster_type = slurm-srun (or pybnf -t slurm-srun) starts the workers ' + 'with srun, inside the allocation SLURM already granted.') + hints.append( + 'The other: start a dask scheduler and workers yourself, by whatever means your ' + 'cluster supports, and give PyBNF the scheduler file with -s or the ' + 'scheduler_file key. PyBNF then only connects to a cluster that is already up.') + return hints + # ----------------------------------------------------------------------- # # The srun launcher (#614, ADR-0122): bring the cluster up without an SSH # login, by asking SLURM to place the workers inside the allocation it has diff --git a/tests/test_cluster.py b/tests/test_cluster.py index adc72ccf..541a43ff 100644 --- a/tests/test_cluster.py +++ b/tests/test_cluster.py @@ -498,7 +498,7 @@ def test_the_node_list_is_read_with_a_program_that_is_installed(self, monkeypatc class TestSetupCluster: def _patch(self, monkeypatch, granted=None, affinity=4, cpu=64, - returncode=None, stderr_bytes=b''): + returncode=None, output_bytes=b''): """Patch what setup_cluster touches: Popen (capture the command), time.sleep (don't actually wait 10s), and every source the default worker count can come from, so the count is deterministic *and* it is visible which @@ -507,15 +507,17 @@ def _patch(self, monkeypatch, granted=None, affinity=4, cpu=64, affinity/cgroup count dask derives, and the whole machine's ``cpu_count()``. The three defaults are deliberately three different numbers. The fake proc's ``poll()`` returns ``returncode`` (None = still running, - the healthy default); if ``stderr_bytes`` is given the fake writes it to - the stderr file setup_cluster handed to Popen, so the early-exit error - path can read it back. Returns the recorder list of Popen (args, kwargs).""" + the healthy default); if ``output_bytes`` is given the fake writes it to + the capture file setup_cluster handed to Popen, so the early-exit error + path can read it back. It is written to the **stdout** handle because that + is the stream dask explains an SSH failure on (#618), and because stderr is + merged into it. Returns the recorder list of Popen (args, kwargs).""" popen_calls = [] def fake_popen(*args, **kwargs): popen_calls.append((args, kwargs)) - if stderr_bytes: - kwargs['stderr'].write(stderr_bytes) + if output_bytes: + kwargs['stdout'].write(output_bytes) return _FakeDaskProc(returncode) monkeypatch.setattr(cluster, 'Popen', fake_popen) @@ -542,11 +544,10 @@ def test_default_worker_count_is_what_the_job_was_granted(self, monkeypatch): assert args[0] == [*DASK_SSH, 'n1', 'n2', '--log-directory', '/out', '--nthreads', '1', '--nworkers', '7'] assert kwargs.get('shell', False) is False # no shell -> no injection - assert kwargs['stdout'] is cluster.DEVNULL - # stderr is captured to a readable file (not discarded), so an early - # bring-up failure can be surfaced — see test_failed_bringup_*. - assert kwargs['stderr'] is not cluster.DEVNULL - assert hasattr(kwargs['stderr'], 'read') + # Both streams are captured to one readable file (nothing is discarded), so an + # early bring-up failure can be surfaced — see test_failed_bringup_*. + assert hasattr(kwargs['stdout'], 'read') + assert kwargs['stderr'] is cluster.STDOUT def test_default_worker_count_is_not_the_size_of_the_machine(self, monkeypatch): """#616, stated as the reported case: a job granted 4 CPUs of a @@ -630,19 +631,179 @@ def test_running_proc_is_returned_without_raising(self, monkeypatch): proc = cluster.Cluster.setup_cluster('n1', '/log', parallel_count=1) assert proc.poll() is None - def test_failed_bringup_raises_with_stderr(self, monkeypatch): + def test_failed_bringup_raises_with_the_captured_output(self, monkeypatch): """If dask ssh has already exited after the startup wait, the cluster never came up. setup_cluster must raise PybnfError (not return a dead - proc that later surfaces as an opaque Client connection error), and the - captured stderr is included for diagnosis.""" + proc that later surfaces as an opaque Client connection error), and + everything dask ssh said is included for diagnosis.""" self._patch(monkeypatch, returncode=1, - stderr_bytes=b'ssh: connect to host node9 port 22: Connection refused') + output_bytes=b'ssh: connect to host node9 port 22: Connection refused') with pytest.raises(printing.PybnfError) as exc: cluster.Cluster.setup_cluster('node9', '/log', parallel_count=1) msg = str(exc.value) assert 'code 1' in msg assert 'Connection refused' in msg + def test_bringup_captures_the_stream_dask_explains_itself_on(self, monkeypatch): + """#618: dask's own account of a failed login -- the node it was connecting + to and the exception paramiko raised -- is ``print``ed, i.e. written to + **stdout**; only the traceback falls to stderr. Sending stdout to DEVNULL + discarded the half of the output that names the cause, which is how a + refused login reached the user as a bare exit code. Oracle: what dask writes + to stdout comes back in the message.""" + self._patch(monkeypatch, returncode=1, + output_bytes=b'[ dask ssh ] : SSH connection error when connecting to ' + b'node9:22\n SSH reported this exception: ' + b'Authentication failed.\n') + with pytest.raises(printing.PybnfError) as exc: + cluster.Cluster.setup_cluster('node9', '/log', parallel_count=1) + assert 'SSH reported this exception: Authentication failed.' in str(exc.value) + + def test_dask_is_run_unbuffered_so_its_own_account_survives(self, monkeypatch): + """#618, and the reason capturing stdout is worth anything: dask ends a failed + bring-up with ``os._exit(1)``, which does not flush Python's buffers. Its + stdout, writing to a file, is block-buffered, and its few hundred bytes of + explanation never reach the 8 KB that would force a write -- so the whole of + it is discarded at exit. Measured against dask 2026.7.1 on a login that + fails: 0 of dask's own lines survive without ``PYTHONUNBUFFERED``, all 15 + with it. The rest of the environment is passed through, since the workers dask + starts inherit it (PATH, a loaded module's variables, BNGPATH).""" + monkeypatch.setenv('BNGPATH', '/opt/bng') + popen_calls = self._patch(monkeypatch) + cluster.Cluster.setup_cluster('n1', '/log', parallel_count=1) + + (_, kwargs), = popen_calls + assert kwargs['env']['PYTHONUNBUFFERED'] == '1' + assert kwargs['env']['BNGPATH'] == '/opt/bng' + + def test_traceback_frames_are_folded_out_of_the_message(self, monkeypatch): + """What dask ssh writes on a failed login is mostly traceback -- one per node + per retry, a dozen frames of dask's and paramiko's own source each -- and the + sentences that say what happened are buried in it, or pushed out of the + message by them. The frames come out of the message; the exception line each + traceback ends with, and dask's own lines, stay.""" + self._patch(monkeypatch, returncode=1, output_bytes=( + b'[ dask ssh ] : SSH connection error when connecting to node9:22\n' + b'Traceback (most recent call last):\n' + b' File "/x/distributed/deploy/old_ssh.py", line 47, in async_ssh\n' + b' ssh.connect(\n' + b' ^^^^^^^^^^^^\n' + b'paramiko.ssh_exception.AuthenticationException: Authentication failed.\n' + b' Retrying... (attempt 1/3)\n')) + with pytest.raises(printing.PybnfError) as exc: + cluster.Cluster.setup_cluster('node9', '/log', parallel_count=1) + message = exc.value.message + assert 'SSH connection error when connecting to node9:22' in message + assert 'AuthenticationException: Authentication failed.' in message + assert 'Retrying... (attempt 1/3)' in message # indented, but not a frame + assert 'old_ssh.py' not in message # the frames themselves + assert 'Traceback' not in message + + def test_the_log_keeps_the_frames_the_message_folds(self, monkeypatch, caplog): + """The folding is a choice about the *message*, which a user reads once and + has to act on. Nothing is lost: the log keeps the output as it was written, + for whoever ends up reading the traceback.""" + self._patch(monkeypatch, returncode=1, output_bytes=( + b'Traceback (most recent call last):\n' + b' File "/x/distributed/deploy/old_ssh.py", line 47, in async_ssh\n' + b'paramiko.ssh_exception.AuthenticationException: Authentication failed.\n')) + with caplog.at_level('ERROR', logger='pybnf.cluster'): + with pytest.raises(printing.PybnfError): + cluster.Cluster.setup_cluster('node9', '/log', parallel_count=1) + line, = [r.message for r in caplog.records if 'dask ssh exited' in r.message] + assert 'old_ssh.py' in line + + def test_a_login_failure_is_named_as_one(self, monkeypatch): + """#618: the reported case was a failed login, and nothing in the message + said so. When the output carries the vocabulary of a refused credential, the + message says the login is the likely cause and says what PyBNF logs in with + -- a library that can offer only a public key or a password -- since that is + what makes the failure survive ``ssh-keygen``, and makes plain ``ssh`` + succeeding from the same shell no evidence at all.""" + self._patch(monkeypatch, returncode=1, + output_bytes=b'paramiko.ssh_exception.AuthenticationException: ' + b'Authentication failed.') + with pytest.raises(printing.PybnfError) as exc: + cluster.Cluster.setup_cluster('node9', '/log', parallel_count=1) + message = exc.value.message + assert 'login' in message + assert 'paramiko' in message + assert 'public key' in message and 'password' in message + assert 'host-based' in message and 'GSSAPI' in message + + def test_a_network_failure_is_not_blamed_on_the_login(self, monkeypatch): + """The converse, and the reason the test above is not satisfied by saying + "login" every time: a machine that could not be reached at all is a + different problem, and answering it with advice about keys and passwords + would send the user off to fix something that is not broken.""" + self._patch(monkeypatch, returncode=1, + output_bytes=b'paramiko.ssh_exception.NoValidConnectionsError: ' + b'[Errno None] Unable to connect to port 22 on 10.0.0.9') + with pytest.raises(printing.PybnfError) as exc: + cluster.Cluster.setup_cluster('node9', '/log', parallel_count=1) + message = exc.value.message + assert 'failed login' not in message # no diagnosis is offered + assert 'public key' not in message + assert 'Unable to connect to port 22' in message # ... but the output is quoted + + def test_failure_names_both_ways_of_running_without_a_login(self, monkeypatch): + """#618: the failure ends the run, so the message is the whole of what the + user gets, and both ways of using several machines that never log in + anywhere are named -- srun inside the allocation (#614) and a scheduler file + naming a cluster that is already up. Named whatever the cause, since + anything that stops dask ssh leaves them as the ways forward: this is the + no-login-vocabulary case.""" + self._patch(monkeypatch, returncode=1, output_bytes=b'exit status 127') + with pytest.raises(printing.PybnfError) as exc: + cluster.Cluster.setup_cluster('node9', '/log', parallel_count=1) + message = exc.value.message + assert 'slurm-srun' in message + assert 'scheduler_file' in message + + def test_output_is_reported_even_when_there_is_none(self, monkeypatch): + """#618: the old message quoted the captured output only when it happened to + be non-empty, and otherwise said "Check the cluster log directory" without + naming a directory -- so a user could not tell a silent failure from one + whose explanation had been thrown away. Silence is now reported as such, and + the directory the nodes write to is named.""" + self._patch(monkeypatch, returncode=1, output_bytes=b'') + with pytest.raises(printing.PybnfError) as exc: + cluster.Cluster.setup_cluster('node9', '/logdir', parallel_count=1) + message = exc.value.message + assert 'no output' in message + assert '/logdir' in message + + def test_captured_output_is_logged_as_well_as_raised(self, monkeypatch, caplog): + """The message goes to a user who may not have kept the terminal; the log is + the copy that survives. Both carry what dask ssh said.""" + self._patch(monkeypatch, returncode=1, output_bytes=b'Authentication failed.') + with caplog.at_level('ERROR', logger='pybnf.cluster'): + with pytest.raises(printing.PybnfError): + cluster.Cluster.setup_cluster('node9', '/log', parallel_count=1) + line, = [r.message for r in caplog.records if 'dask ssh exited' in r.message] + assert 'Authentication failed.' in line + + def test_colour_codes_are_stripped_from_the_quoted_output(self, monkeypatch): + """dask wraps its failure lines in terminal colour escapes. Quoted as they + are, they reach the log file and the message as literal characters.""" + self._patch(monkeypatch, returncode=1, + output_bytes=b'\x1b[91mSSH connection failed after 3 retries.\x1b[0m') + with pytest.raises(printing.PybnfError) as exc: + cluster.Cluster.setup_cluster('node9', '/log', parallel_count=1) + assert 'SSH connection failed after 3 retries.' in str(exc.value) + assert '\x1b' not in exc.value.message + + def test_only_the_tail_of_a_long_output_is_quoted(self, monkeypatch): + """One failure per node, each retried three times, would otherwise put + hundreds of lines in front of the advice at the end of the message.""" + self._patch(monkeypatch, returncode=1, + output_bytes=b'\n'.join(b'line %i' % i for i in range(200))) + with pytest.raises(printing.PybnfError) as exc: + cluster.Cluster.setup_cluster('node9', '/log', parallel_count=1) + quoted = str(exc.value) + assert 'line 199' in quoted + assert 'line 0\n' not in quoted + def test_parallel_count_divides_per_node_with_ceil(self, monkeypatch): """With an explicit parallel_count, workers are spread over nodes: n_per_node = ceil(parallel_count / num_nodes). 5 threads over 3 nodes ⇒