Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Failed login generating EOF / socket error #1563

Closed
johnarnold opened this issue Feb 8, 2020 · 11 comments
Closed

Failed login generating EOF / socket error #1563

johnarnold opened this issue Feb 8, 2020 · 11 comments

Comments

@johnarnold
Copy link

Netmiko version 2.4.2 and 3.0.0

I'm connecting to a cisco OOB/console router via ssh, to get serial console access to a juniper router. Using redispatch to flip drivers after connecting successfully. I don't think any of that matters... I'm erroring out inside base_connection.telnet_login()... The problem i'm seeing is when we cycle through credentials to get the correct local credential for the juniper router.

In netmiko 1.4.3 it works fine -- get a login prompt, send credentials, login fails, send again, , repeat until a NetMikoAuthenticationException is raised, catch it, try the next credential.

Connected successfully to 'oob01.cisco1' via Console [1.2.3.4]
No cached named secret found for 'WanSecrets'. Refreshing secret.
Fetched named secret username/password
read_channel: 
write_channel: b'\r\n'
read_channel: 
NOTICE NOTICE NOTICE 
Unauthorized access and/or use prohibited. All access and/or use subject to monitoring.
NOTICE NOTICE NOTICE
FreeBSD/amd64 (juniper_router) (ttyu0)
login: 
write_channel: b'root\r\n'
read_channel: root
password: 
write_channel: b'wrong_password\r\n'
read_channel: 
Login incorrect
login: login: 
write_channel: b'\r\n'
read_channel: 
login: login: 
write_channel: b'root\r\n'
read_channel: root
password: 
write_channel: b'wrong_password\r\n'
read_channel: 
Login incorrect
write_channel: b'\r\n'
read_channel: 
write_channel: b'\r\n'
read_channel: 
write_channel: b'\r\n'
write_channel: b'\r\n'
read_channel: 
Authentication failed for roo*****************:wro*****************@juniper_router via Device Terminal [None]
read_channel: login: login: login: login: login: login: login: login: login: login: Login attempt timed out after 120 seconds
NOTICE NOTICE NOTICE 
Unauthorized access and/or use prohibited. All access and/or use subject to monitoring.
NOTICE NOTICE NOTICE
FreeBSD/amd64 (juniper_router) (ttyu0)
login: 
write_channel: b'root\r\n'
read_channel: root
password: 
write_channel: b'wrong_password2\r\n'
read_channel: 
Login incorrect
login: login: 
write_channel: b'\r\n'
read_channel: 
login: login: 
write_channel: b'root\r\n'
read_channel: root
password: 
write_channel: b'wrong_password2\r\n'
read_channel: 
Login incorrect
write_channel: b'\r\n'
read_channel: 
write_channel: b'\r\n'
read_channel: 
write_channel: b'\r\n'
read_channel: 
write_channel: b'\r\n'
write_channel: b'\r\n'
read_channel: 
login: login: login: login: login: login: login: login: login: login: login: login: 
Authentication failed for roo*****************:wro*****************@juniper_router via Device Terminal [None]
read_channel: 
write_channel: b'\r\n'
read_channel: 
login: login: 
write_channel: b'root\r\n'
read_channel: root
password: 
write_channel: b'right_password\r\n'
read_channel: 
Last login: Fri Feb  7 20:39:05 on ttyu0
--- JUNOS 17.4X5.9 Kernel 64-bit  JNPR-11.0-20190825.5ca39af_buil
root@juniper_router1:~ # 

In netmiko 2.4.2, we send an EOF after the login failure:

Connected successfully to 'oob01.cisco1' via Console [10.64.85.89]
No cached named secret found for 'WanSecrets'. Refreshing secret.
Fetched named secret username/password
read_channel: 
write_channel: b'\r\n'
read_channel: 
NOTICE NOTICE NOTICE 
Unauthorized access and/or use prohibited. All access and/or use subject to monitoring.
NOTICE NOTICE NOTICE
FreeBSD/amd64 (juniper_router) (ttyu0)
login: 
write_channel: b'root\r\n'
read_channel: root
password: 
write_channel: b'wrong_password\r\n'
read_channel: 
Login incorrect
login: login: 
write_channel: b'\r\n'
read_channel: 
login: login: 
write_channel: b'root\r\n'
read_channel: root
password: 
write_channel: b'wrong_password\r\n'
read_channel: 
Login incorrect
write_channel: b'\r\n'
read_channel: 
write_channel: b'\r\n'
read_channel: 
write_channel: b'\r\n'
write_channel: b'\r\n'
read_channel: 
[chan 0] EOF sent (0)
Authentication failed for roo*****************:rC1*****************@juniper_router via Device Terminal [None]
[chan 0] EOF received (0)
EOF in transport thread

The code for telnet_login is structured such that it should catch an EOFError:

            except EOFError:
                msg = "Telnet login failed: {0}".format(self.host)
                raise NetMikoAuthenticationException(msg)

... however, no EOFError is ever raised. Instead, its an OSError "socket is closed" when we try the next telnet_login with new credential / send on the channel.

Help wanted...

Why is an EOF being sent from the client?
Are we hitting a channel receive timeout? I have the same max_loops value for 1.4.3 as for 2.4.2.

Thanks,
John

@ktbyers
Copy link
Owner

ktbyers commented Feb 9, 2020

Have you looked at it in the Python debugger? Looking at the code in Netmiko 3.0.0 (which for this code should be very similar to 2.4.2), I don't see anything that would cause us to send an EOF.

Probably should be testing only Netmiko 3.0.0 as any issue/fix would be based on that.

@johnarnold
Copy link
Author

@ktbyers Yes, I've stepped through the code in pycharm for 1.4.3, 2.4.2 and 3.0.0. I don't see any significant change in netmiko, and suspect the EOF is coming from paramiko somewhere, but nevertheless it works when I roll back to 1.4.3... Perhaps there's some global timeout difference that I just haven't identified?

@ktbyers
Copy link
Owner

ktbyers commented Feb 10, 2020

Can you post the full stack trace for the Netmiko 3.0.0 error?

@johnarnold
Copy link
Author

@ktbyers

logger.exception(e)
Socket is closed
Traceback (most recent call last):
  File "/home/johnar/scripts-lib/approved-internal-libraries/lib/python/packages/net-devices2/net_devices2/drivers/__init__.py", line 1296, in _try_local_auth
    timeout_backoff_delay_factor
  File "/home/johnar/scripts-lib/approved-internal-libraries/lib/python/packages/net-devices2/net_devices2/drivers/__init__.py", line 1072, in _connect_terminal
    max_loops=5,
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/netmiko/base_connection.py", line 717, in telnet_login
    self.write_channel(self.TELNET_RETURN)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/netmiko/base_connection.py", line 427, in write_channel
    self._write_channel(out_data)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/netmiko/base_connection.py", line 385, in _write_channel
    self.remote_conn.sendall(write_bytes(out_data, encoding=self.encoding))
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/paramiko/channel.py", line 846, in sendall
    sent = self.send(s)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/paramiko/channel.py", line 801, in send
    return self._send(s, m)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/paramiko/channel.py", line 1198, in _send
    raise socket.error("Socket is closed")
OSError: Socket is closed

I believe this is on the next login attempt read_channel(), after the EOF is sent / socket closed:

Login incorrect
write_channel: b'\r\n'
read_channel: 
write_channel: b'\r\n'
read_channel: 
write_channel: b'\r\n'
write_channel: b'\r\n'
read_channel: 
[chan 0] EOF sent (0)
Authentication failed for roo*****************:wro*****************@juniper_router via Device Terminal [None]
[chan 0] EOF received (0)
EOF in transport thread
read_channel: 

@johnarnold
Copy link
Author

@ktbyers I believe this is the stack trace close to when the EOF is being sent (I set a breakpoint on the paramiko _log() function)

import traceback
traceback.print_stack()
  File "/snap/pycharm-community/178/plugins/python-ce/helpers/pydev/pydevd.py", line 2127, in <module>
    main()
  File "/snap/pycharm-community/178/plugins/python-ce/helpers/pydev/pydevd.py", line 2118, in main
    globals = debugger.run(setup['file'], None, None, is_module)
  File "/snap/pycharm-community/178/plugins/python-ce/helpers/pydev/pydevd.py", line 1427, in run
    return self._exec(is_module, entry_point_fn, module_name, file, globals, locals)
  File "/snap/pycharm-community/178/plugins/python-ce/helpers/pydev/pydevd.py", line 1434, in _exec
    pydev_imports.execfile(file, globals, locals)  # execute the script
  File "/snap/pycharm-community/178/plugins/python-ce/helpers/pydev/_pydev_imps/_pydev_execfile.py", line 18, in execfile
    exec(compile(contents+"\n", file, 'exec'), glob, loc)
  File "/snap/pycharm-community/178/plugins/python-ce/helpers/pycharm/_jb_pytest_runner.py", line 43, in <module>
    sys.exit(pytest.main(args, plugins_to_load + [Plugin]))
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/config/__init__.py", line 90, in main
    return config.hook.pytest_cmdline_main(config=config)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/manager.py", line 92, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/manager.py", line 86, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/main.py", line 230, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/main.py", line 193, in wrap_session
    session.exitstatus = doit(config, session) or 0
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/main.py", line 237, in _main
    config.hook.pytest_runtestloop(session=session)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/manager.py", line 92, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/manager.py", line 86, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/main.py", line 258, in pytest_runtestloop
    item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/manager.py", line 92, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/manager.py", line 86, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/runner.py", line 80, in pytest_runtest_protocol
    runtestprotocol(item, nextitem=nextitem)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/runner.py", line 95, in runtestprotocol
    reports.append(call_and_report(item, "call", log))
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/runner.py", line 176, in call_and_report
    call = call_runtest_hook(item, when, **kwds)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/runner.py", line 201, in call_runtest_hook
    lambda: ihook(item=item, **kwds), when=when, reraise=reraise
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/runner.py", line 229, in from_call
    result = func()
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/runner.py", line 201, in <lambda>
    lambda: ihook(item=item, **kwds), when=when, reraise=reraise
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/manager.py", line 92, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/manager.py", line 86, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/runner.py", line 125, in pytest_runtest_call
    item.runtest()
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/python.py", line 1423, in runtest
    self.ihook.pytest_pyfunc_call(pyfuncitem=self)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/hooks.py", line 286, in __call__
    return self._hookexec(self, self.get_hookimpls(), kwargs)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/manager.py", line 92, in _hookexec
    return self._inner_hookexec(hook, methods, kwargs)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/manager.py", line 86, in <lambda>
    firstresult=hook.spec.opts.get("firstresult") if hook.spec else False,
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/pluggy/callers.py", line 187, in _multicall
    res = hook_impl.function(*args)
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/_pytest/python.py", line 170, in pytest_pyfunc_call
    result = testfunction(**testargs)
  File "/home/johnar/scripts-lib/approved-internal-libraries/lib/python/packages/net-devices2/test/test_connect.py", line 278, in test_wan_console
    h.connect(use_mgmt=False, use_loopback=False, use_console=True, use_service_account=False)
  File "/home/johnar/scripts-lib/approved-internal-libraries/lib/python/packages/net-devices2/net_devices2/drivers/__init__.py", line 157, in wrapper
    f(self, *args, **kwargs)
  File "/home/johnar/scripts-lib/approved-internal-libraries/lib/python/packages/net-devices2/net_devices2/drivers/__init__.py", line 915, in connect
    dest_port_type=ConnectionType.console
  File "/home/johnar/scripts-lib/approved-internal-libraries/lib/python/packages/net-devices2/net_devices2/drivers/__init__.py", line 785, in connect_via_method
    self._try_auth(read_write, ip, dest_port_type, self._connect_direct)
  File "/home/johnar/scripts-lib/approved-internal-libraries/lib/python/packages/net-devices2/net_devices2/drivers/__init__.py", line 943, in _try_auth
    DEFAULT_GLOBAL_DELAY_FACTOR)
  File "/home/johnar/scripts-lib/approved-internal-libraries/lib/python/packages/net-devices2/net_devices2/drivers/__init__.py", line 1158, in _connect_direct
    self._console_preparation()
  File "/home/johnar/scripts-lib/approved-internal-libraries/lib/python/packages/net-devices2/net_devices2/drivers/__init__.py", line 1103, in _console_preparation
    connection_method=self._connect_terminal
  File "/home/johnar/scripts-lib/approved-internal-libraries/lib/python/packages/net-devices2/net_devices2/utilities.py", line 320, in wrapper
    return f(self, *args, **kwds)
  File "/home/johnar/scripts-lib/approved-internal-libraries/lib/python/packages/net-devices2/net_devices2/drivers/__init__.py", line 1182, in _try_with_local_account
    self._try_local_auth(credential, dest_port_type, ip, secret_name, connection_method)
  File "/home/johnar/scripts-lib/approved-internal-libraries/lib/python/packages/net-devices2/net_devices2/drivers/__init__.py", line 1296, in _try_local_auth
    timeout_backoff_delay_factor
  File "/home/johnar/scripts-lib/approved-internal-libraries/lib/python/packages/net-devices2/net_devices2/drivers/__init__.py", line 1072, in _connect_terminal
    max_loops=5,
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/netmiko/base_connection.py", line 736, in telnet_login
    self.remote_conn.close()
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/paramiko/channel.py", line 666, in close
    msgs = self._close_internal()
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/paramiko/channel.py", line 1255, in _close_internal
    m1 = self._send_eof()
  File "/home/johnar/Azure-FCS2/nettask-venv/lib/python3.6/site-packages/paramiko/channel.py", line 1248, in _send_eof
    self._log(DEBUG, "EOF sent ({})".format(self._name))
  File "/snap/pycharm-community/178/plugins/python-ce/helpers/pydev/pydevd.py", line 1099, in do_wait_suspend
    self._do_wait_suspend(thread, frame, event, arg, suspend_type, from_this_thread)
  File "/snap/pycharm-community/178/plugins/python-ce/helpers/pydev/pydevd.py", line 1113, in _do_wait_suspend
    self.process_internal_commands()
  File "/snap/pycharm-community/178/plugins/python-ce/helpers/pydev/pydevd.py", line 818, in process_internal_commands
    int_cmd.do_it(self)
  File "/snap/pycharm-community/178/plugins/python-ce/helpers/pydev/_pydevd_bundle/pydevd_comm.py", line 1647, in do_it
    result = pydevd_console_integration.console_exec(self.thread_id, self.frame_id, self.expression, dbg)
  File "/snap/pycharm-community/178/plugins/python-ce/helpers/pydev/_pydevd_bundle/pydevd_console_integration.py", line 222, in console_exec
    Exec(code, updated_globals, updated_globals)
  File "/snap/pycharm-community/178/plugins/python-ce/helpers/pydev/_pydevd_bundle/pydevd_exec2.py", line 3, in Exec
    exec(exp, global_vars, local_vars)
  File "<input>", line 1, in <module>

@johnarnold
Copy link
Author

I found the difference:

1.4.3:

raise NetMikoAuthenticationException(msg)

        msg = "Telnet login failed: {0}".format(self.host)
        raise NetMikoAuthenticationException(msg)

3.0.0 / develop:
https://github.com/ktbyers/netmiko/blob/develop/netmiko/base_connection.py#L735

        msg = f"Login failed: {self.host}"
        self.remote_conn.close()
        raise NetmikoAuthenticationException(msg)

Netmiko is forcing a connection close on login failure.
From: #835

@johnarnold
Copy link
Author

Our code was written with the (previously true) assumption that the transport/channel is managed separately from the login/authentication. Thus, we can try multiple credentials to get a successful login without reconnecting. Is it really the right thing to close the connection because of a failed login, is this expected behavior?

@ktbyers
Copy link
Owner

ktbyers commented Feb 11, 2020

Yes, I think it probably is the right thing to do for the telnet_login() method which is where that code resides.

In the typical case the telnet_login() failing would indicate the telnet connection was dead and we should probably clean it up.

Netmiko, however, has the serial_login() call telnet_login code as the code is essentially identical here. And you could make a good case that in the serial_login situation this isn't the right behavior (i.e. that the connection should be just left open).

So I guess we could add an argument into telnet_login() like connection_close=False and pass that in as argument (and then condition that self.remote_conn.close() based on that argument).

Does that sound reasonable?

@johnarnold
Copy link
Author

@ktbyers yes, I was going to suggest a parameter like close_on_authfail=True and just override it... would you like me to PR that in?

@ktbyers
Copy link
Owner

ktbyers commented Feb 11, 2020 via email

@ktbyers
Copy link
Owner

ktbyers commented Mar 1, 2022

I don't think this was ever done. I am going to close as there isn't any active work on the issue.

@ktbyers ktbyers closed this as completed Mar 1, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants