SSH User not consistent across all remote execution tasks

Support
,
1

Problem:

Foreman does not use the SSH user set in Administer → Settings → Remote Execution → SSH User for all remote execution tasks.

In my testing, I’d like to use a SSH user / password that set under the Remote Execution tab under settings (set to service.foreman in my deployment);
Foreman uses this user for select tasks (e.g. running Ansible Roles);
Foreman uses a combination of the set SSH User (service.foreman) and user “foreman-proxy” when remotely upgrading packages;

In my deployment I have the user (service.foreman) setup in FreeIPA. All my managed Foreman hosts are part of the same REALM. SSH logins / automount functions correctly and as expected.

My objective is to have an IPA managed service user with appropriate SUDO / login permissions for Foreman / Katello functions.

I’m struggling to understand the corralation of various remote execution authentication schemes Foreman uses (as documented):

  1. SSH User / Password;
  2. SSH User / Keys;
  3. SSH keys only.

I’d apprechaite a link to a document refernece where this is clearly defined.

Expected outcome:

Set SSH User and SSH Password should be consistently applied and used for all remote execution tasks.

Foreman and Proxy versions:

Foreman master + proxy: 3.12.0
Katello: 4.14

Distribution and version:

Rocky EL 9.4

Other relevant data:
Host logs when running Ansible Roles remotely:

Oct 29 11:15:00 fmtest3.domain.local kernel: FS-Cache: Loaded
Oct 29 11:15:00 fmtest3.domain.local kernel: Key type dns_resolver registered
Oct 29 11:15:00 fmtest3.domain.local kernel: NFS: Registering the id_resolver key type
Oct 29 11:15:00 fmtest3.domain.local kernel: Key type id_resolver registered
Oct 29 11:15:00 fmtest3.domain.local kernel: Key type id_legacy registered
Oct 29 11:15:00 fmtest3.domain.local systemd[1]: Starting SSSD Kerberos Cache Manager...
Oct 29 11:15:00 fmtest3.domain.local systemd[1]: Started SSSD Kerberos Cache Manager.
Oct 29 11:15:00 fmtest3.domain.local sssd_kcm[1564]: Starting up
Oct 29 11:15:00 fmtest3.domain.local nfsrahead[1581]: setting /home/remote/service.foreman readahead to 128
Oct 29 11:15:01 fmtest3.domain.local sshd[1550]: Accepted publickey for service.foreman from 10.1.80.10 port 39812 ssh2: RSA SHA256:guHsMhUM5T+Fb+jr9cGu6E1KhseEn4xdXeFANPRJu08
Oct 29 11:15:01 fmtest3.domain.local systemd-logind[714]: New session 3 of user service.foreman.
Oct 29 11:15:01 fmtest3.domain.local systemd[1]: Created slice User Slice of UID 390000008.
Oct 29 11:15:01 fmtest3.domain.local systemd[1]: Starting User Runtime Directory /run/user/390000008...
Oct 29 11:15:01 fmtest3.domain.local systemd[1]: Finished User Runtime Directory /run/user/390000008.
Oct 29 11:15:01 fmtest3.domain.local systemd[1]: Starting User Manager for UID 390000008...
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: pam_unix(systemd-user:session): session opened for user service.foreman(uid=390000008) by service.foreman(uid=0)
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Queued start job for default target Main User Target.
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Created slice User Application Slice.
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Started Mark boot as successful after the user session has run 2 minutes.
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Started Daily Cleanup of User's Temporary Directories.
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Reached target Paths.
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Reached target Timers.
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Starting D-Bus User Message Bus Socket...
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Starting Create User's Volatile Files and Directories...
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Listening on D-Bus User Message Bus Socket.
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Reached target Sockets.
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Finished Create User's Volatile Files and Directories.
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Reached target Basic System.
Oct 29 11:15:01 fmtest3.domain.local systemd[1]: Started User Manager for UID 390000008.
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Reached target Main User Target.
Oct 29 11:15:01 fmtest3.domain.local systemd[1589]: Startup finished in 102ms.
Oct 29 11:15:01 fmtest3.domain.local systemd[1]: Started Session 3 of User service.foreman.
Oct 29 11:15:01 fmtest3.domain.local sshd[1550]: pam_unix(sshd:session): session opened for user service.foreman(uid=390000008) by service.foreman(uid=0)
Oct 29 11:15:02 fmtest3.domain.local python3[1617]: ansible-ansible.legacy.setup Invoked with gather_subset=['all'] gather_timeout=10 filter=[] fact_path=/etc/ansible/facts.d
Oct 29 11:15:17 fmtest3.domain.local systemd[1]: systemd-hostnamed.service: Deactivated successfully.

Host logs when applifing a package update remotely:

Oct 29 11:21:23 fmtest3.domain.local systemd[1]: Starting SSSD Kerberos Cache Manager...
Oct 29 11:21:23 fmtest3.domain.local systemd[1]: Started SSSD Kerberos Cache Manager.
Oct 29 11:21:23 fmtest3.domain.local sssd_kcm[1677]: Starting up
Oct 29 11:21:24 fmtest3.domain.local sshd[1672]: pam_sss(sshd:auth): authentication success; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.1.80.10 user=service.foreman
Oct 29 11:21:24 fmtest3.domain.local sshd[1672]: Accepted password for service.foreman from 10.1.80.10 port 53300 ssh2
Oct 29 11:21:24 fmtest3.domain.local systemd-logind[714]: New session 5 of user service.foreman.
Oct 29 11:21:24 fmtest3.domain.local systemd[1]: Created slice User Slice of UID 390000008.
Oct 29 11:21:24 fmtest3.domain.local systemd[1]: Starting User Runtime Directory /run/user/390000008...
Oct 29 11:21:24 fmtest3.domain.local systemd[1]: Finished User Runtime Directory /run/user/390000008.
Oct 29 11:21:24 fmtest3.domain.local systemd[1]: Starting User Manager for UID 390000008...
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: pam_unix(systemd-user:session): session opened for user service.foreman(uid=390000008) by service.foreman(uid=0)
Oct 29 11:21:24 fmtest3.domain.local nfsrahead[1697]: setting /home/remote/service.foreman readahead to 128
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Queued start job for default target Main User Target.
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Created slice User Application Slice.
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Started Mark boot as successful after the user session has run 2 minutes.
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Started Daily Cleanup of User's Temporary Directories.
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Reached target Paths.
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Reached target Timers.
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Starting D-Bus User Message Bus Socket...
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Starting Create User's Volatile Files and Directories...
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Finished Create User's Volatile Files and Directories.
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Listening on D-Bus User Message Bus Socket.
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Reached target Sockets.
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Reached target Basic System.
Oct 29 11:21:24 fmtest3.domain.local systemd[1]: Started User Manager for UID 390000008.
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Reached target Main User Target.
Oct 29 11:21:24 fmtest3.domain.local systemd[1680]: Startup finished in 187ms.
Oct 29 11:21:24 fmtest3.domain.local systemd[1]: Started Session 5 of User service.foreman.
Oct 29 11:21:24 fmtest3.domain.local sshd[1672]: pam_unix(sshd:session): session opened for user service.foreman(uid=390000008) by service.foreman(uid=0)
Oct 29 11:21:24 fmtest3.domain.local sshd[1672]: pam_unix(sshd:session): session closed for user service.foreman
Oct 29 11:21:24 fmtest3.domain.local systemd-logind[714]: Session 5 logged out. Waiting for processes to exit.
Oct 29 11:21:24 fmtest3.domain.local systemd[1]: session-5.scope: Deactivated successfully.
Oct 29 11:21:24 fmtest3.domain.local systemd-logind[714]: Removed session 5.
Oct 29 11:21:24 fmtest3.domain.local sshd[1708]: pam_sss(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.1.80.10 user=foreman-proxy
Oct 29 11:21:24 fmtest3.domain.local sshd[1708]: pam_sss(sshd:auth): received for user foreman-proxy: 7 (Authentication failure)
Oct 29 11:21:27 fmtest3.domain.local sshd[1706]: error: PAM: Authentication failure for foreman-proxy from 10.1.80.10
Oct 29 11:21:27 fmtest3.domain.local sshd[1711]: pam_sss(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.1.80.10 user=foreman-proxy
Oct 29 11:21:27 fmtest3.domain.local sshd[1711]: pam_sss(sshd:auth): received for user foreman-proxy: 7 (Authentication failure)
Oct 29 11:21:29 fmtest3.domain.local sshd[1706]: error: PAM: Authentication failure for foreman-proxy from 10.1.80.10
Oct 29 11:21:29 fmtest3.domain.local sshd[1714]: pam_sss(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.1.80.10 user=foreman-proxy
Oct 29 11:21:29 fmtest3.domain.local sshd[1714]: pam_sss(sshd:auth): received for user foreman-proxy: 7 (Authentication failure)
Oct 29 11:21:30 fmtest3.domain.local sshd[1706]: error: PAM: Authentication failure for foreman-proxy from 10.1.80.10
Oct 29 11:21:30 fmtest3.domain.local sshd[1706]: Failed none for foreman-proxy from 10.1.80.10 port 53316 ssh2
Oct 29 11:21:30 fmtest3.domain.local sshd[1706]: Failed password for foreman-proxy from 10.1.80.10 port 53316 ssh2
Oct 29 11:21:30 fmtest3.domain.local sshd[1706]: Failed password for foreman-proxy from 10.1.80.10 port 53316 ssh2
Oct 29 11:21:30 fmtest3.domain.local sshd[1706]: error: maximum authentication attempts exceeded for foreman-proxy from 10.1.80.10 port 53316 ssh2 [preauth]
Oct 29 11:21:30 fmtest3.domain.local sshd[1706]: Disconnecting authenticating user foreman-proxy 10.1.80.10 port 53316: Too many authentication failures [preauth]
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Activating special unit Exit the Session...
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Stopped target Main User Target.
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Stopped target Basic System.
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Stopped target Paths.
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Stopped target Sockets.
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Stopped target Timers.
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Stopped Mark boot as successful after the user session has run 2 minutes.
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Stopped Daily Cleanup of User's Temporary Directories.
Oct 29 11:21:34 fmtest3.domain.local systemd[1]: Stopping User Manager for UID 390000008...
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Closed D-Bus User Message Bus Socket.
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Stopped Create User's Volatile Files and Directories.
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Removed slice User Application Slice.
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Reached target Shutdown.
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Finished Exit the Session.
Oct 29 11:21:34 fmtest3.domain.local systemd[1680]: Reached target Exit the Session.
Oct 29 11:21:34 fmtest3.domain.local systemd[1]: user@390000008.service: Deactivated successfully.
Oct 29 11:21:34 fmtest3.domain.local systemd[1]: Stopped User Manager for UID 390000008.
Oct 29 11:21:34 fmtest3.domain.local systemd[1]: Stopping User Runtime Directory /run/user/390000008...
Oct 29 11:21:34 fmtest3.domain.local systemd[1]: run-user-390000008.mount: Deactivated successfully.
Oct 29 11:21:34 fmtest3.domain.local systemd[1]: user-runtime-dir@390000008.service: Deactivated successfully.
Oct 29 11:21:34 fmtest3.domain.local systemd[1]: Stopped User Runtime Directory /run/user/390000008.
Oct 29 11:21:34 fmtest3.domain.local systemd[1]: Removed slice User Slice of UID 390000008.
2

Also, forgot to mention that Foreman Job logs (Web GUI), display the following error:

1: Error initializing command: RuntimeError - Unable to create directory /var/tmp/foreman-ssh-cmd-39933b22-e4e0-48ad-be1b-d82f7d9e525a on remote system, exit code: 255
   2:
Exit status: EXCEPTION
   3:
StandardError: Job execution failed
3

All these things can be set in multiple places, while the ones which are placed “closer to the host” win over the more general ones. For example you can set a remote_execution_ssh_user parameter on the host and that one will override the one from the settings. If the one from settings is not being used, then you probably have something set somewhere that acts as an override.

Considering in both examples you gave the service.foreman user is let in at least once, I wouldn’t necessarily expect a problem in this area.

When opening a connection, the ssh user is set as a user. If password is provided, an attempt with it is made. For Script, password is tried first, not sure in which order ansible tries things.

The smart proxy machine has its key in ~foreman-proxy/.ssh/id_rsa_foreman_proxy. When opening connection to the remote host, SSH user is used along with this key.

I’m not sure how this differs from the one above. There is always an ssh user, you can’t attempt to connect to a remote host without an user.

It means it was able to log in, but then things went south on the remote end. Try resolving this first.

On a more general note, if you increase the log level to debug in /etc/foreman-proxy/settings.yaml and restart foreman-proxy, /var/log/foreman-proxy/proxy.log will contain all the exact commands that were executed, which should give you a fuller picture about what is used when and how.

4

Thank you for this. Very helpful. I was able to get it work, however quite as you described…

Please assume SUDO is configured accordinly in IPA for service.foreman to run priviledged commands.

  1. I set the SSH User and Effective User to service.foreman
  2. I cleared, the SSH password configured in Foreman for user service.foreman
  3. I copied the foreman proxy public keys into my IPA-managed service.foreman user account
  4. I reset sss cache on the host

Foreman is now able to login and perform the tasks that failed previously.

HOWEVER,

When I specify a password for the SSH user (service.foreman) in Foreman settings, the flow does not work (even through I’m able to login interactively via SSH using the same credentials).

Questions:

  1. Passwordless operation is great and my desired outcome, why doesn’t password authentication work?
  2. In a multi smartproxy scenario (one per geographic location), I’m assuming each proxy would have differnet SSH keys. (currently the foreman-proxy keys are different on -master and -proxy host). Is the correct approach to ensure my IPA service.foreman user have all foreman -master and -proxy server public keys listed?

Logs are below for review.

Seperate question (I appologize upfront from bunching this side topic into this ticket):

  • The remote action I’m executing is updating an individual package (fmtest3 host is Rocky EL 9.4).
  • Upon successful task completion, the updated package does not reflect accurately in Foreman’s Content view (still shows package as upgradable) even through I’m able to confirm the host was upgraded with correct RPM version (via hostside rpm -qa | grep “packagename”).
  • What callback / Ansible Role should be called to update host packages to Foreman?

Log from host:

Oct 29 12:58:52 fmtest3.domain.local systemd[1]: session-36.scope: Deactivated successfully.
Oct 29 12:58:52 fmtest3.domain.local systemd[1]: session-36.scope: Consumed 6.020s CPU time.
Oct 29 12:58:52 fmtest3.domain.local systemd-logind[714]: Removed session 36.
Oct 29 13:00:27 fmtest3.domain.local systemd[1]: Starting SSSD Kerberos Cache Manager...
Oct 29 13:00:27 fmtest3.domain.local systemd[1]: Started SSSD Kerberos Cache Manager.
Oct 29 13:00:27 fmtest3.domain.local sssd_kcm[2707]: Starting up
Oct 29 13:00:27 fmtest3.domain.local sshd[2702]: pam_sss(sshd:auth): authentication success; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.1.80.10 user=service.foreman
Oct 29 13:00:27 fmtest3.domain.local sshd[2702]: Accepted password for service.foreman from 10.1.80.10 port 39764 ssh2
Oct 29 13:00:27 fmtest3.domain.local systemd-logind[714]: New session 37 of user service.foreman.
Oct 29 13:00:27 fmtest3.domain.local systemd[1]: Started Session 37 of User service.foreman.
Oct 29 13:00:27 fmtest3.domain.local sshd[2702]: pam_unix(sshd:session): session opened for user service.foreman(uid=390000008) by service.foreman(uid=0)
Oct 29 13:00:27 fmtest3.domain.local sshd[2702]: pam_unix(sshd:session): session closed for user service.foreman
Oct 29 13:00:27 fmtest3.domain.local systemd-logind[714]: Session 37 logged out. Waiting for processes to exit.
Oct 29 13:00:27 fmtest3.domain.local systemd[1]: session-37.scope: Deactivated successfully.
Oct 29 13:00:27 fmtest3.domain.local systemd-logind[714]: Removed session 37.
Oct 29 13:00:27 fmtest3.domain.local sshd[2713]: pam_sss(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.1.80.10 user=foreman-proxy
Oct 29 13:00:27 fmtest3.domain.local sshd[2713]: pam_sss(sshd:auth): received for user foreman-proxy: 7 (Authentication failure)
Oct 29 13:00:30 fmtest3.domain.local sshd[2711]: error: PAM: Authentication failure for foreman-proxy from 10.1.80.10
Oct 29 13:00:30 fmtest3.domain.local sshd[2715]: pam_sss(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.1.80.10 user=foreman-proxy
Oct 29 13:00:30 fmtest3.domain.local sshd[2715]: pam_sss(sshd:auth): received for user foreman-proxy: 7 (Authentication failure)
Oct 29 13:00:31 fmtest3.domain.local sshd[2711]: error: PAM: Authentication failure for foreman-proxy from 10.1.80.10
Oct 29 13:00:32 fmtest3.domain.local sshd[2717]: pam_sss(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=10.1.80.10 user=foreman-proxy
Oct 29 13:00:32 fmtest3.domain.local sshd[2717]: pam_sss(sshd:auth): received for user foreman-proxy: 7 (Authentication failure)
Oct 29 13:00:34 fmtest3.domain.local sshd[2711]: error: PAM: Authentication failure for foreman-proxy from 10.1.80.10
Oct 29 13:00:34 fmtest3.domain.local sshd[2711]: Failed none for foreman-proxy from 10.1.80.10 port 39770 ssh2
Oct 29 13:00:34 fmtest3.domain.local sshd[2711]: Failed password for foreman-proxy from 10.1.80.10 port 39770 ssh2
Oct 29 13:00:34 fmtest3.domain.local sshd[2711]: Failed password for foreman-proxy from 10.1.80.10 port 39770 ssh2
Oct 29 13:00:34 fmtest3.domain.local sshd[2711]: error: maximum authentication attempts exceeded for foreman-proxy from 10.1.80.10 port 39770 ssh2 [preauth]
Oct 29 13:00:34 fmtest3.domain.local sshd[2711]: Disconnecting authenticating user foreman-proxy 10.1.80.10 port 39770: Too many authentication failures [preauth]
Oct 29 13:01:01 fmtest3.domain.local CROND[2720]: (root) CMD (run-parts /etc/cron.hourly)
Oct 29 13:01:01 fmtest3.domain.local run-parts[2723]: (/etc/cron.hourly) starting 0anacron
Oct 29 13:01:01 fmtest3.domain.local run-parts[2729]: (/etc/cron.hourly) finished 0anacron
Oct 29 13:01:01 fmtest3.domain.local CROND[2719]: (root) CMDEND (run-parts /etc/cron.hourly)
Oct 29 13:05:27 fmtest3.domain.local sssd_kcm[2707]: Shutting down (status = 0)
Oct 29 13:05:27 fmtest3.domain.local systemd[1]: sssd-kcm.service: Deactivated successfully.

Log from Proxy:


2024-10-29T13:00:27 5421beeb [I] Started POST /dynflow/tasks/launch 
2024-10-29T13:00:27 5421beeb [D] verifying remote client 10.0.80.10 against trusted_hosts ["stackmgmt-master.global.o", "stackmgmt-proxy.domain.local"]
2024-10-29T13:00:27 5421beeb [D] ExecutionPlan b55974db-6ded-4b93-8b07-7a43d828c808      pending >>  planning
2024-10-29T13:00:27 5421beeb [D]          Step b55974db-6ded-4b93-8b07-7a43d828c808: 1   pending >>   running in phase     Plan Proxy::Dynflow::Action::Batch
2024-10-29T13:00:27 5421beeb [D]          Step b55974db-6ded-4b93-8b07-7a43d828c808: 1   running >>   success in phase     Plan Proxy::Dynflow::Action::Batch
2024-10-29T13:00:27 5421beeb [D] ExecutionPlan b55974db-6ded-4b93-8b07-7a43d828c808     planning >>   planned
2024-10-29T13:00:27 5421beeb [I] Finished POST /dynflow/tasks/launch with 200 (11.88 ms)
2024-10-29T13:00:27  [D] ExecutionPlan b55974db-6ded-4b93-8b07-7a43d828c808      planned >>   running
2024-10-29T13:00:27  [D]          Step b55974db-6ded-4b93-8b07-7a43d828c808: 2   pending >>   running in phase      Run Proxy::Dynflow::Action::Batch
2024-10-29T13:00:27 5421beeb [D] ExecutionPlan 50a228d9-a5d1-4322-93fa-3d8cb33abc4f      pending >>  planning
2024-10-29T13:00:27 5421beeb [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 1   pending >>   running in phase     Plan Proxy::RemoteExecution::Ssh::Actions::RunScript
2024-10-29T13:00:27 5421beeb [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 2   pending >>   running in phase     Plan Proxy::RemoteExecution::Ssh::Actions::ScriptRunner
2024-10-29T13:00:27 5421beeb [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 5   pending >>   running in phase     Plan Proxy::Dynflow::Callback::Action
2024-10-29T13:00:27 5421beeb [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 5   running >>   success in phase     Plan Proxy::Dynflow::Callback::Action
2024-10-29T13:00:27 5421beeb [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 2   running >>   success in phase     Plan Proxy::RemoteExecution::Ssh::Actions::ScriptRunner
2024-10-29T13:00:27 5421beeb [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 1   running >>   success in phase     Plan Proxy::RemoteExecution::Ssh::Actions::RunScript
2024-10-29T13:00:27 5421beeb [D] ExecutionPlan 50a228d9-a5d1-4322-93fa-3d8cb33abc4f     planning >>   planned
2024-10-29T13:00:27 5421beeb [D]          Step b55974db-6ded-4b93-8b07-7a43d828c808: 2   running >>   success in phase      Run Proxy::Dynflow::Action::Batch
2024-10-29T13:00:27  [D] ExecutionPlan 50a228d9-a5d1-4322-93fa-3d8cb33abc4f      planned >>   running
2024-10-29T13:00:27  [D] ExecutionPlan b55974db-6ded-4b93-8b07-7a43d828c808      running >>   stopped
2024-10-29T13:00:27  [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 3   pending >>   running in phase      Run Proxy::RemoteExecution::Ssh::Actions::ScriptRunner
2024-10-29T13:00:27 5421beeb [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 3   running >> suspended in phase      Run Proxy::RemoteExecution::Ssh::Actions::ScriptRunner
2024-10-29T13:00:27  [D] start runner f0e89178-0dc8-4d84-9600-fa98ef122a7f
2024-10-29T13:00:27  [D] Checking if private key has passphrase: ssh-keygen -y -f /var/lib/foreman-proxy/ssh/id_rsa_foreman_proxy
2024-10-29T13:00:27  [D] close: 10.0.80.10:55300
2024-10-29T13:00:27  [D] Private key is not protected with a passphrase
2024-10-29T13:00:27  [D] Running: {"SSHPASS"=>"*****"} sshpass -e ssh -o User=service.foreman -o Port=22 -o IdentityFile=/var/lib/foreman-proxy/ssh/id_rsa_foreman_proxy -o IdentitiesOnly=yes -o StrictHostKeyChecking=accept-new -o LogLevel=error -o ControlMaster=auto -o ControlPath=/var/tmp/f0e89178-0dc8-4d84-9600-fa98ef122a7f -o ControlPersist=yes -o ServerAliveInterval=15 -o ServerAliveCountMax=3 -o PreferredAuthentications=password -o NumberOfPasswordPrompts=1 fmtest3.domain.local true
2024-10-29T13:00:27  [D] Established connection using authentication method password
2024-10-29T13:00:27  [D] copying script to /var/tmp/foreman-ssh-cmd-f0e89178-0dc8-4d84-9600-fa98ef122a7f/script:
  | #!/bin/sh
  | exec true
2024-10-29T13:00:27  [D] Running: ssh -o ControlPath=/var/tmp/f0e89178-0dc8-4d84-9600-fa98ef122a7f -o LogLevel=quiet fmtest3.domain.local mkdir -p /var/tmp/foreman-ssh-cmd-f0e89178-0dc8-4d84-9600-fa98ef122a7f
2024-10-29T13:00:34  [E] error while initializing command RuntimeError Unable to create directory /var/tmp/foreman-ssh-cmd-f0e89178-0dc8-4d84-9600-fa98ef122a7f on remote system, exit code: 255:
 /usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.11.3/lib/smart_proxy_remote_execution_ssh/runners/script_runner.rb:386:in `ensure_remote_command'
/usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.11.3/lib/smart_proxy_remote_execution_ssh/runners/script_runner.rb:378:in `ensure_remote_directory'
/usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.11.3/lib/smart_proxy_remote_execution_ssh/runners/script_runner.rb:356:in `upload_data'
/usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.11.3/lib/smart_proxy_remote_execution_ssh/runners/script_runner.rb:352:in `cp_script_to_remote'
/usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.11.3/lib/smart_proxy_remote_execution_ssh/runners/script_runner.rb:166:in `preflight_checks'
/usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.11.3/lib/smart_proxy_remote_execution_ssh/runners/script_runner.rb:151:in `start'
/usr/share/gems/gems/smart_proxy_dynflow-0.9.3/lib/smart_proxy_dynflow/runner/dispatcher.rb:35:in `start_runner'
/usr/share/gems/gems/dynflow-1.9.0/lib/dynflow/actor.rb:13:in `on_message'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/context.rb:46:in `on_envelope'
/usr/share/gems/gems/smart_proxy_dynflow-0.9.3/lib/smart_proxy_dynflow/runner/dispatcher.rb:27:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/dynflow-1.9.0/lib/dynflow/actor.rb:122:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/usr/share/gems/gems/dynflow-1.9.0/lib/dynflow/actor.rb:56:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/core.rb:162:in `process_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/core.rb:96:in `block in on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/core.rb:119:in `block (2 levels) in schedule_execution'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `block in synchronize'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/core.rb:116:in `block in schedule_execution'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/serialized_execution.rb:18:in `call'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/serialized_execution.rb:96:in `work'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:352:in `run_task'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:343:in `block (3 levels) in create_worker'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `loop'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `block (2 levels) in create_worker'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `catch'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `block in create_worker'
/usr/share/gems/gems/logging-2.4.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2024-10-29T13:00:34  [E] Error initializing command - RuntimeError Unable to create directory /var/tmp/foreman-ssh-cmd-f0e89178-0dc8-4d84-9600-fa98ef122a7f on remote system, exit code: 255:
/usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.11.3/lib/smart_proxy_remote_execution_ssh/runners/script_runner.rb:386:in `ensure_remote_command'
/usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.11.3/lib/smart_proxy_remote_execution_ssh/runners/script_runner.rb:378:in `ensure_remote_directory'
/usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.11.3/lib/smart_proxy_remote_execution_ssh/runners/script_runner.rb:356:in `upload_data'
/usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.11.3/lib/smart_proxy_remote_execution_ssh/runners/script_runner.rb:352:in `cp_script_to_remote'
/usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.11.3/lib/smart_proxy_remote_execution_ssh/runners/script_runner.rb:166:in `preflight_checks'
/usr/share/gems/gems/smart_proxy_remote_execution_ssh-0.11.3/lib/smart_proxy_remote_execution_ssh/runners/script_runner.rb:151:in `start'
/usr/share/gems/gems/smart_proxy_dynflow-0.9.3/lib/smart_proxy_dynflow/runner/dispatcher.rb:35:in `start_runner'
/usr/share/gems/gems/dynflow-1.9.0/lib/dynflow/actor.rb:13:in `on_message'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/context.rb:46:in `on_envelope'
/usr/share/gems/gems/smart_proxy_dynflow-0.9.3/lib/smart_proxy_dynflow/runner/dispatcher.rb:27:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/dynflow-1.9.0/lib/dynflow/actor.rb:122:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/usr/share/gems/gems/dynflow-1.9.0/lib/dynflow/actor.rb:56:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/core.rb:162:in `process_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/core.rb:96:in `block in on_envelope'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/core.rb:119:in `block (2 levels) in schedule_execution'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `block in synchronize'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'
/usr/share/gems/gems/concurrent-ruby-edge-0.6.0/lib/concurrent-ruby-edge/concurrent/actor/core.rb:116:in `block in schedule_execution'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/serialized_execution.rb:18:in `call'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/serialized_execution.rb:96:in `work'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:352:in `run_task'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:343:in `block (3 levels) in create_worker'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `loop'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `block (2 levels) in create_worker'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `catch'
/usr/share/gems/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `block in create_worker'
/usr/share/gems/gems/logging-2.4.0/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2024-10-29T13:00:34  [D] refresh runner f0e89178-0dc8-4d84-9600-fa98ef122a7f
2024-10-29T13:00:34  [D] refreshing runner
2024-10-29T13:00:34  [D] finish runner f0e89178-0dc8-4d84-9600-fa98ef122a7f
2024-10-29T13:00:34  [D] closing session for command [f0e89178-0dc8-4d84-9600-fa98ef122a7f],0 actors left 
2024-10-29T13:00:34  [D] terminate f0e89178-0dc8-4d84-9600-fa98ef122a7f
2024-10-29T13:00:34  [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 3 got event #<Proxy::Dynflow::Runner::Update:0x00007f6de80b0f10>
2024-10-29T13:00:34  [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 3 suspended >>   running in phase      Run Proxy::RemoteExecution::Ssh::Actions::ScriptRunner
2024-10-29T13:00:34 5421beeb [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 3   running >>   success in phase      Run Proxy::RemoteExecution::Ssh::Actions::ScriptRunner
2024-10-29T13:00:34  [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 6   pending >>   running in phase      Run Proxy::Dynflow::Callback::Action
2024-10-29T13:00:34 5421beeb [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 6   running >>   success in phase      Run Proxy::Dynflow::Callback::Action
2024-10-29T13:00:34  [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 4   pending >>   running in phase Finalize Proxy::RemoteExecution::Ssh::Actions::ScriptRunner
2024-10-29T13:00:34 5421beeb [E] Script execution failed
2024-10-29T13:00:34 5421beeb [D]          Step 50a228d9-a5d1-4322-93fa-3d8cb33abc4f: 4   running >>     error in phase Finalize Proxy::RemoteExecution::Ssh::Actions::ScriptRunner
2024-10-29T13:00:34  [D] ExecutionPlan 50a228d9-a5d1-4322-93fa-3d8cb33abc4f      running >>   stopped
2024-10-29T13:00:38  [D] Executor heartbeat
2024-10-29T13:00:53  [D] Executor heartbeat
2024-10-29T13:01:08  [D] Executor heartbeat
5

Update to the above question…

I resolved it by changing the effective SUDO user to root (previsouly set to service.foreman).

I’m able now able to see updated packages in foreman on EL hosts.

I’m not able to get updates for DEB hosts (Ubuntu in this case) via the ATIX subscription manager port. Is there anything specific that needs to be done / modified (with Ansible) to get this to work?

6

Oh, I think I see what’s happening, although I’m not sure why. With the first ssh command, we try to establish a multiplexed ssh connection. This connection is expected to stay open while the job is being executed and subsequent invocations of ssh are expected to reuse this connection. What seems to be happening on your end, is that the connection gets established and then immediately closed. Going out on a limb, I would expect that when you use a key the subsequent ssh invocations manage to establish their own connection with the key, while the same thing with password fails as we only provide the password when opening the first connection.

I haven’t seen this happening anywhere else, could it be related to having the hosts enrolled in IPA? Could the enrollment process deploy some ssh/pam/something configs that would prevent the connection from staying up?

7

All I’m using is FreeIPA. The service.foreman account simply has the public SSH keys of the foreman-proxy credential thats on the foreman-master and slave hosts.

I’m still unable to define a password and login via password stragely. But thats a minor issue. Key authentication was my objective provided there is a central method of managing public keys (FreeIPA in my case).

The only other thing I can think of … The all IPA enabled hosts also have autofs configured. So when the service.foreman user logs in the home directory is NFS mounted via autofs. I’m not sure if its permissions related. However I’m not sure how this could be even corralated since this particilar error only happens when a password is specified for the service.foreman user in Foreman Settings.