Running with sudo says "SSH password was requested, but none specified"

[jbscare]

When we run Ansible with sudo on the control host, to run as a different user, we get this error:

fatal: [dom-use-uat17fullstack-01]: UNREACHABLE! => {"changed": false, "msg": "SSH password was requested, but none specified", "unreachable": true}

This happens with Mitogen 0.2.3, and the latest master version from Git (df3a418 right now), and does not happen with Mitogen 0.2.2. Amazon Linux 18.03 and Python 2.7.14 on both control and target hosts.

-vvv output:

TASK [api : check if MySQL is running] *****************************************
task path: /home/jsmift/ansible/dom/roles/api/tasks/main.yml:58
[pid 113399] 13:19:46.050039 D mitogen: unix.connect(path='/tmp/mitogen_unix_jjEzBm')
[pid 113399] 13:19:46.050785 D mitogen: unix.connect(): local ID is 2003, remote is 0
[pid 113235] 13:19:46.050829 D mitogen: register(Context(2003, None), mitogen.core.Stream(u'unix_client.113399'))
[pid 113399] 13:19:46.051100 D mitogen: register(Context(0, None), mitogen.core.Stream(u'unix_listener.113235'))
[pid 113399] 13:19:49.194455 D mitogen: Context(0, None).call_service_async(u'ansible_mitogen.services.ContextService', u'get', {'stack': [{u'method': u'ssh', u'kwargs': {u'username': None, u'check_host_keys': u'ignore', u'ssh_debug_level': None, u'hostname': u'172.20.128.27', u'identities_only': False, u'identity_file': None, u'connect_timeout': 10, u'python_path': None, u'ssh_path': u'ssh', u'password': None, u'port': None, u'ssh_args': [u'-o', u'ControlMaster=auto', u'-o', u'ControlPersist=60s', u'-o', u'ControlPath=/tmp/ssh-socket-%r-at-%h-%p-as-%u-112364']}}, {u'enable_lru': True, u'method': u'sudo', u'kwargs': {u'username': u'root', u'sudo_path': None, u'python_path': None, u'password': None, u'sudo_args': [u'-H', u'-S', u'-n'], u'connect_timeout': 10}}]})
[pid 113399] 13:19:49.194915 D mitogen: Context(0, None).send_async(Message(0, 2003, 2003, 110, 1000, "\x80\x02X'\x00\x00\x00ansible_mitogen.services.ContextServiceq\x01X\x03"..773))
[pid 113235] 13:19:49.195818 D mitogen: mitogen.ssh.Stream(u'default').connect()
[pid 113235] 13:19:49.208560 D mitogen: create_child() child 113578 fd 65, parent 113235, cmd: ssh -o "LogLevel ERROR" -o "Compression yes" -o "ServerAliveInterval 15" -o "ServerAliveCountMax 3" -o "BatchMode yes" -o "StrictHostKeyChecking no" -o "UserKnownHostsFile /dev/null" -o "GlobalKnownHostsFile /dev/null" -o ControlMaster=auto -o ControlPersist=60s -o ControlPath=/tmp/ssh-socket-%r-at-%h-%p-as-%u-112364 172.20.128.27 python -c "'import codecs,os,sys;_=codecs.decode;exec(_(_(\"eNqFkU9Lw0AQxc/Np8htd+k23W1QIRBQehAPIgSxBy2SPxNdm+4um6Sx/fROU6FJPXib3743+4aZhK9iUwdWWaDMc7wbkCp9hNK4DWWRN8G6aO2CCi6FYGdO+JAcqvLEeWVqoMkQ3BBWQ+gQMLDeY3yVNpi69ePYJ0XqOqWJn+qiF+Eb8rZJswp6ed7Wbp4pPbf75tNognNOLmzTuG/cgauV0a9RuO5jQe+UQyZ3yf2LIOt43HbyIFZ0LPAxTgndqsZ8gI6+QG9qhW+3hdnO2hpmbaOqmZAB1gG+BXnq4AA60NBEUoaL8IoR5mFQ51QDVHLy+PD8JIR40wQHzE2Bd2DeMn6nx0sUxoLG/ROXERY4SAsqw+ubkHFyUBZ/Km189q046TJyPE5pfwOWfX1a+IW7+8/9d0o5mvIH5mm5Ig==\".encode(),\"base64\"),\"zip\"))'"
[pid 113235] 13:19:49.210012 D mitogen: mitogen.ssh.Stream(u'local.113578').connect(): stdin=65, stdout=30, diag=70
[pid 113235] 13:19:49.273600 D mitogen: mitogen.ssh.Stream(u'local.113578'): received 'Permission denied (publickey,password,keyboard-interactive).\r\n'
[pid 113235] 13:19:49.273930 D mitogen: mitogen.ssh.Stream(u'local.113578').on_disconnect()
[pid 113235] 13:19:49.274193 D mitogen: mitogen.parent.DiagLogStream(fd=70, u'local.113578').on_disconnect()
[pid 113235] 13:19:49.274753 D mitogen: mitogen.ssh.Stream(u'local.113578'): PID 113578 exited with return code 255
[pid 113399] 13:19:49.275483 D mitogen: Broker(0x7f1e70c62450).shutdown()
[pid 113399] 13:19:49.275900 D mitogen: mitogen.core.Stream(u'unix_listener.113235').on_disconnect()
[pid 113235] 13:19:49.276248 D mitogen: mitogen.core.Stream(u'unix_client.113399').on_disconnect()
[pid 113399] 13:19:49.276236 D mitogen: Context(0, None).on_disconnect()
[pid 113235] 13:19:49.276501 D mitogen: Context(2003, None).on_disconnect()
[pid 113399] 13:19:49.276505 D mitogen: Waker(Broker(0x7f1e70c62450) rfd=15, wfd=16).on_shutdown()
[pid 113399] 13:19:49.276767 D mitogen: Waker(Broker(0x7f1e70c62450) rfd=15, wfd=16).on_disconnect()
fatal: [dom-use-uat17fullstack-01]: UNREACHABLE! => {
    "changed": false, 
    "msg": "SSH password was requested, but none specified", 
    "unreachable": true
}

PLAY RECAP *********************************************************************
dom-use-uat17fullstack-01  : ok=1    changed=0    unreachable=1    failed=0   

[pid 113235] 13:19:49.281699 D mitogen: Broker(0x7f1e70cf4610).shutdown()
[pid 113235] 13:19:49.282601 D mitogen: mitogen.ssh.Stream(u'ssh.172.20.128.27') closing CALL_FUNCTION channel
[pid 113235] 13:19:49.282782 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-6'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.282908 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-8'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.282965 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-5'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.283056 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-9'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.283244 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-7'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.283334 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-10'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.283555 D mitogen: mitogen.parent.DiagLogStream(fd=67, u'ssh.172.20.128.27').on_shutdown()
[pid 113235] 13:19:49.283733 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-11'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.283815 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-13'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.283890 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-12'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.283984 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-14'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.284061 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-15'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.284131 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-0'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.284310 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-2'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.284491 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-1'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.284637 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-4'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.284691 I mitogen: mitogen.service.Pool(0x7f1e70cf4e90, size=16, th='mitogen.service.Pool.7f1e70cf4e90.worker-3'): channel or latch closed, exitting: None
[pid 113235] 13:19:49.286295 D mitogen: mitogen.parent.DiagLogStream(fd=67, u'ssh.172.20.128.27').on_disconnect()
[pid 113235] 13:19:49.289110 D mitogen: Waker(Broker(0x7f1e70cf4610) rfd=9, wfd=12).on_shutdown()
[pid 113235] 13:19:49.289363 D mitogen: Waker(Broker(0x7f1e70cf4610) rfd=9, wfd=12).on_disconnect()
[pid 113235] 13:19:49.291279 D mitogen.ctx.ssh.172.20.128.27: mitogen: Waker(Broker(0x7ff4edd6ad50) rfd=3, wfd=4).on_disconnect()
[pid 113235] 13:19:49.291521 D mitogen.ctx.ssh.172.20.128.27: mitogen: mitogen.fork.Stream(u'fork.10577') closing CALL_FUNCTION channel
[pid 113235] 13:19:49.291736 D mitogen.ctx.ssh.172.20.128.27: mitogen: mitogen.parent.DiagLogStream(fd=17, u'sudo.root').on_disconnect()
[pid 113235] 13:19:49.291919 D mitogen.ctx.ssh.172.20.128.27: mitogen: mitogen.sudo.Stream(u'sudo.root') closing CALL_FUNCTION channel
[pid 113235] 13:19:49.292109 D mitogen.ctx.ssh.172.20.128.27: mitogen: <IoLogger stdout>.on_disconnect()
[pid 113235] 13:19:49.292297 D mitogen.ctx.ssh.172.20.128.27: mitogen: <IoLogger stderr>.on_disconnect()
[pid 113235] 13:19:49.292757 D mitogen.ctx.ssh.172.20.128.27.sudo.root: mitogen: mitogen.fork.Stream(u'fork.10583') closing CALL_FUNCTION channel
[pid 113235] 13:19:49.293139 D mitogen.ctx.ssh.172.20.128.27.sudo.root: mitogen: Waker(Broker(0x7f97f3d9ab10) rfd=3, wfd=4).on_disconnect()
[pid 113235] 13:19:49.293325 D mitogen.ctx.ssh.172.20.128.27.sudo.root: mitogen: <IoLogger stderr>.on_disconnect()
[pid 113235] 13:19:49.293500 D mitogen.ctx.ssh.172.20.128.27.sudo.root: mitogen: <IoLogger stdout>.on_disconnect()
[pid 113235] 13:19:49.294217 D mitogen.ctx.fork.10577: mitogen: _on_shutdown_msg(Message(3, 2, 2, 106, 0, ''..0))
[pid 113235] 13:19:49.294717 D mitogen.ctx.ssh.172.20.128.27: mitogen: mitogen.fork.Stream(u'fork.10577').on_disconnect()
[pid 113235] 13:19:49.294922 D mitogen.ctx.ssh.172.20.128.27: mitogen: RouteMonitor(): mitogen.fork.Stream(u'fork.10577') is gone; propagating DEL_ROUTE for set([3])
[pid 113235] 13:19:49.295107 D mitogen.ctx.ssh.172.20.128.27: mitogen: Router(Broker(0x7ff4edd6ad50)).del_route(3)
[pid 113235] 13:19:49.295283 D mitogen: RouteMonitor(): firing local disconnect for Context(3, u'fork.10577')
[pid 113235] 13:19:49.295443 D mitogen: RouteMonitor(): deleting route to 3 via mitogen.ssh.Stream(u'ssh.172.20.128.27')
[pid 113235] 13:19:49.295589 D mitogen: Router(Broker(0x7f1e70cf4610)).del_route(3)
[pid 113235] 13:19:49.295757 D mitogen.ctx.ssh.172.20.128.27: mitogen: mitogen.fork.Stream(u'fork.10577'): child process still alive, sending SIGTERM
[pid 113235] 13:19:49.295958 D mitogen.ctx.fork.10583: mitogen: _on_shutdown_msg(Message(1003, 4, 4, 106, 0, ''..0))
[pid 113235] 13:19:49.301503 D mitogen: mitogen.ssh.Stream(u'ssh.172.20.128.27').on_disconnect()
[pid 113235] 13:19:49.301694 D mitogen: RouteMonitor(): mitogen.ssh.Stream(u'ssh.172.20.128.27') is gone; propagating DEL_ROUTE for set([2, 4, 1003])
[pid 113235] 13:19:49.301858 D mitogen: Router(Broker(0x7f1e70cf4610)).del_route(2)
[pid 113235] 13:19:49.302017 I ansible_mitogen.services: ContextService(): Forgetting Context(2, u'ssh.172.20.128.27') due to stream disconnect
[pid 113235] 13:19:49.302197 D mitogen: Router(Broker(0x7f1e70cf4610)).del_route(4)
[pid 113235] 13:19:49.302348 I ansible_mitogen.services: ContextService(): Forgetting Context(4, u'ssh.172.20.128.27.sudo.root') due to stream disconnect
[pid 113235] 13:19:49.302515 D mitogen: Router(Broker(0x7f1e70cf4610)).del_route(1003)
[pid 113235] 13:19:49.302669 D mitogen: mitogen.parent.DiagLogStream(fd=67, u'ssh.172.20.128.27').on_disconnect()
[pid 113235] 13:19:49.302850 D mitogen: mitogen.ssh.Stream(u'ssh.172.20.128.27'): PID 113269 exited with return code 255
WARNING: ansible-playbook exited with non-zero status (4)

Config changes:

+$ ansible-config dump --only-changed
ANSIBLE_SSH_RETRIES(/ansible/dom/ansible.cfg) = 2
DEFAULT_FORKS(/ansible/dom/ansible.cfg) = 20
DEFAULT_MANAGED_STR(/ansible/dom/ansible.cfg) = ansible managed
DEFAULT_PRIVATE_KEY_FILE(/ansible/dom/ansible.cfg) = /home/ansible/.ssh/id_rsa
DEFAULT_REMOTE_USER(/ansible/dom/ansible.cfg) = ansible
DEFAULT_STRATEGY(/ansible/dom/ansible.cfg) = mitogen_linear
DEFAULT_STRATEGY_PLUGIN_PATH(/ansible/dom/ansible.cfg) = [u'/ansible/shared/plugins/mitogen/ansible_mitogen/plugins/strategy']
DEFAULT_TRANSPORT(/ansible/dom/ansible.cfg) = ssh
HOST_KEY_CHECKING(/ansible/dom/ansible.cfg) = False
RETRY_FILES_ENABLED(/ansible/dom/ansible.cfg) = False
SYSTEM_WARNINGS(/ansible/dom/ansible.cfg) = False

[jbscare]

This line in the log output, YAML-ified for readability::

stack:
- kwargs:
    check_host_keys: ignore
    connect_timeout: 10
    hostname: 172.20.128.27
    identities_only: false
    identity_file: null
    password: null
    port: null
    python_path: null
    ssh_args: [-o, ControlMaster=auto, -o, ControlPersist=60s, -o, ControlPath=/tmp/ssh-socket-%r-at-%h-%p-as-%u-112364]
    ssh_debug_level: null
    ssh_path: ssh
    username: null
  method: ssh
- enable_lru: true
  kwargs:
    connect_timeout: 10
    password: null
    python_path: null
    sudo_args: [-H, -S, -n]
    sudo_path: null
    username: root
  method: sudo

Does that username: null in the first kwargs dict there imply that it's not picking up DEFAULT_REMOTE_USER(/ansible/dom/ansible.cfg) = ansible from our config?

I checked with Mitogen 0.2.2, and I see this in the log:

[pid 30463] 13:31:50.980249 D mitogen: Context(0, None).call_service_async(u'ansible_mitogen.services.ContextService', u'get', {'stack': [{u'method': u'ssh', u'kwargs': {u'username': u'ansible', u'check_host_keys': u'ignore', u'ssh_debug_level': None, u'hostname': u'172.20.128.27', u'identity_file': u'/home/ansible/.ssh/id_rsa', u'connect_timeout': 10, u'python_path': [u'/usr/bin/python'], u'ssh_path': u'ssh', u'password': None, u'port': None, u'ssh_args': [u'-o', u'ControlMaster=auto', u'-o', u'ControlPersist=60s', u'-o', u'ControlPath=/tmp/ssh-socket-%r-at-%h-%p-as-%u-29773']}}, {u'enable_lru': True, u'method': u'sudo', u'kwargs': {u'username': u'root', u'sudo_path': None, u'python_path': [u'/usr/bin/python'], u'password': None, u'sudo_args': [u'-H', u'-S', u'-n'], u'connect_timeout': 10}}]})

YAML-ified:

stack:
- kwargs:
    check_host_keys: ignore
    connect_timeout: 10
    hostname: 172.20.128.27
    identity_file: /home/ansible/.ssh/id_rsa
    password: null
    port: null
    python_path: [/usr/bin/python]
    ssh_args: [-o, ControlMaster=auto, -o, ControlPersist=60s, -o, ControlPath=/tmp/ssh-socket-%r-at-%h-%p-as-%u-29773]
    ssh_debug_level: null
    ssh_path: ssh
    username: ansible
  method: ssh
- enable_lru: true
  kwargs:
    connect_timeout: 10
    password: null
    python_path: [/usr/bin/python]
    sudo_args: [-H, -S, -n]
    sudo_path: null
    username: root
  method: sudo

Looks identical except for username: ansible there.

[dw]

Apologies for the insane delay on this!

Would it be possible to capture the run with -e '{"mitogen_ssh_debug_level": 3}' in addition to -vvv? I'm betting this is a really simple problem, but I can't recall what went into 0.2.3 that could cause it.

Of particular interest is whether SSH is logging debug about trying to use its authentication socket

[jbscare]

Sure thing, attaching a log of that here.

I see some

2019-01-21 11:04:44,354 p=37314 u=jenksible | [pid 38105] 11:04:44.354101 D mitogen: mitogen.ssh.Stream(u'local.38128'): debug1: Control socket "/tmp/ssh-socket-ansible-at-172.20.128.155-22-as-jenksible-37118" does not exist

in there -- is that what you're looking for?

ansible-mitogen.log

[dw]

Does that username: null in the first kwargs dict there imply that it's not picking up DEFAULT_REMOTE_USER(/ansible/dom/ansible.cfg) = ansible from our config?

Yes, it absolutely does :) Apologies, slightly swamped in these and it's making me miss obvious stuff!

Adding a bunch of tests, its clear it only happens for delegate_to. The root cause appears to be the overzealous reworking in 3d58832, it introduced a completely different way to load configs for delegate_to hosts.

[dw]

That commit (issue #340) is only 'fixing' breakage introduced in 1f21a30 for issue #251

[dw]

Hi Josh, sorry for the huge delay on this. I believe the work done in #412 covers your issue too, and the tests have been updated to set a non-default ansible_user cfg variable to catch a recurrence.

Thanks a million!

---

This should now be fixed on the master branch and will make it into the next release. To be updated when a new release is made, subscribe to https://networkgenomics.com/mail/mitogen-announce/

If you are still experiencing the problem on the current master branch, please do not hesitate to reopen this issue.

Thanks for reporting this!