Uyuni 2021.01: OpenSuse 15 bootstraping with venv-salt-minion fails locking registration user account

[phibid]

I can't bootstrap an Opensuse 15 server, ending up with this error:

# spacecmd -u admin -p toto -- system_bootstrap --hostname uyuni05v --ssh-user uyuni --ssh-password uyuni --activation-key 1-opensuse15 --proxyid '1000010030'
INFO: Spacewalk Username: admin
INFO: Connected to https://uyuni.cms.colt/rpc/api as admin
Bootstrapping 'uyuni05v'. This may take a while.
ERROR: redstone.xmlrpc.XmlRpcFault: [JsonParsingError({"return":"","id":"uyuni05v","fun":"state.apply","jid":"20220310105110594636","_stamp":"2022-03-10T10:52:25.239306"}, java.lang.IllegalStateException: Expected BEGIN_OBJECT but was STRING at path $)]

Checking the message of the opensuse client, I can see that the bootstrap begins correctly, however at a certain point, not sure how and why, it seems to be using an incorrect password and consequently lock the user account (see the pam_tally2 errors in the logs):

2022-03-10T11:52:36.866365+01:00 opensuse15 sudo:    uyuni : (command continued) BhdGgpOgogICAgICAgICAgICB1bnBhY2tfZXh0KGV4dF9wYXRo#012KQogICAgICAgIGVsc2U6CiAgICAgICAgICAgIHZlcnNpb25fcGF0aCA9IG9zLnBhdGguam9pbihP#012UFRJT05TLnNhbHRkaXIsICJleHRfdmVyc2lvbiIpCiAgICAgICAgICAgIGlmIG5vdCBvcy5wYXRo#012LmV4aXN0cyh2ZXJzaW9uX3BhdGgpIG9yIG5vdCBvcy5wYXRoLmlzZmlsZSh2ZXJzaW9uX3BhdGgp#012OgogICAgICAgICAgICAgICAgbmVlZF9leHQoKQogICAgICAgICAgICB3aXRoIG9wZW4odmVyc2lv#012bl9wYXRoLCAiciIpIGFzIHZwbzoKICAgICAgICAgICAgICAgIGN1cl92ZXJzaW9uID0gdnBvLnJl#012YWRsaW5lKCkuc3RyaXAoKQogICAgICAgICAgICBpZiBjdXJfdmVyc2lvbiAhPSBPUFRJT05TLmV4#012dF9tb2RzOgogICAgICAgICAgICAgICAgbmVlZF9leHQoKQogICAgIyBGaXggcGFyYW1ldGVyIHBh#012c3NpbmcgaXNzdWUKICAgIGlmIGxlbihBUkdTKSA9PSAxOgogICAgICAgIGFyZ3ZfcHJlcGFyZWQg#012PSBBUkdTWzBdLwbGl0KCkKICAgIGVsc2U6CiAgICAgICAgYXJndl9wcmVwYXJlZCA9IEFSR1MK#012CiAgICBzYWx0X2FyZ3YgPSBbCiAgICAgICAgZ2V0X2V4ZWN1dGFibGUoKSwKICAgICAgICBzYWx0#012X2NhbGxfcGF0aCwKICAgICAgICAiLS1yZXRjb2RlLXBhc3N0aHJvdWdoIiwKICAgICAgICAiLS1s#012b2NhbCIsCiAgICAgICAgIi0tbWV0YWRhdG
2022-03-10T11:52:36.866655+01:00 opensuse15 sudo:    uyuni : (command continued) EiLAogICAgICAgICItLW91dCIsCiAgICAgICAgImpz#012b24iLAogICAgICAgICItbCIsCiAgICAgICAgInF1aWV0IiwKICAgICAgICAiLWMiLAogICAgICAg#012IE9QVElPTlMuc2FsdGRpciwKICAgIF0KCiAgICB0cnk6CiAgICAgICAgaWYgYXJndl9wcmVwYXJl#012ZFstMV0uc3RhcnRzd2l0aCgiLS1uby1wYXJzZT0iKToKICAgICAgICAgICAgc2FsdF9hcmd2LmFw#012cGVuZChhcmd2X3BXBhcmVkLnBvcCgtMSkpCiAgICBleGNlcHQgKEluZGV4RXJyb3IsIFR5cGVF#012cnJvcik6CiAgICAgICAgcGFzcwoKICAgIHNhRfYXJndi5hcHBlbmQoIi0tIikKICAgIHNhbHRf#012YXJndi5leHRlbmQoYXJndl9wcmVwYXJlZCkKCiAgICBzeXMuc3RkZXJyLndyaXRlKCJTQUxUX0FS#012R1Y6IHswfVxuIi5mb3JtYXQoc2FsdF9hcmd2KSkKCiAgICAjIE9ubHkgZW1pdCB0aGUgZGVsaW1p#012dGVyIG9uICpib3RoKiBzdGRvdXQgYW5kIHN0ZGVyciB3aGVuIGNvbXBsZXRlbHkgc3VjY2Vzc2Z1#012bC4KICAgICMgWWVzLCB0aGUgZmx1c2goKSBpcyBuZWNlc3NhcnkuCiAgICBzeXMuc3Rkb3V0Lndy#012aXRlKE9QVElPTlMuZGVsaW1pdGVyICsgIlxuIikKICAgIHN5cy5zdGRvdXQuZmx1c2goKQogICAg#012aWYgbm90IE9QVElPTlMudHR5OgogICAgICAgIHN5cy5zdGRlcnIud3JpdGUoT1BUSU9OUy5kZWxp#012bWl0ZXIgKyAiXG4iKQogICAgICAgIHN5cy5zdGRlcn
2022-03-10T11:52:36.866947+01:00 opensuse15 sudo:    uyuni : (command continued) IuZmx1c2goKQogICAgaWYgT1BUSU9OUy5j#012bWRfdW1hc2sgaXMgbm90IE5vbmU6CiAgICAgICAgb2xkX3VtYXNrID0gb3MudW1hc2soT1BUSU9O#012Uy5jbWRfdW1hc2spICAjIHB5bGludDogZGlzYWJsZT1ibGFja2xpc3RlZC1mdW5jdGlvbgogICAg#012aWYgT1BUSU9OUy50dHk6CiAgICAgICAgcHJvYyA9IHN1YnByb2Nlc3MuUG9wZW4oCiAgICAgICAg#012ICAgIHNhbHRfYXJndiwgc3Rkb3V0PXN1YnByb2Nlc3MuUElQRSwgc3RkZXJyPXN1YnByb2Nlc3Mu#012UElQRQogICAgICAgICkKICAgICAgICAjIFJldHVybnMgYnl0ZXMgaW5zdGVhZCBvZiBzdHJpbmcg#012b24gcHl0aG9uIDMKICAgICAgICBzdGRvdXQsIF8gPSBwcm9jLmNvbW11bmljYXRlKCkKICAgICAg#012ICBzeXMuc3Rkb3V0LndyaXRlKAogICAgICAgICAgICBzdGRvdXQuZGVjb2RlKGVuY29kaW5nPWdl#012dF9zeXN0ZW1fZW5jb2RpbmcoKSwgZXJyb3JzPSJyZXBsYWNlIikKICAgICAgICApCiAgICAgICAg#012c3lzLnN0ZG91dC5mbHVzaCgpCiAgICAgICAgcmV0Y29kZSA9IHByb2MucmV0dXJuY29kZQogICAg#012ICAgIGlmIE9QVElPTlMud2lwZToKICAgICAgICAgICAgc2h1dGlsLnJtdHJlZShPUFRJT05TLnNh#012bHRkaXIpCiAgICBlbGlmIE9QVElPTlMud2lwZToKICAgICAgICByZXRjb2RlID0gc3VicHJvY2Vz#012cy5jYWxsKHNHRfYXJndikKICAgICAgICBzaHV0aWwucm10cm
2022-03-10T11:52:36.867232+01:00 opensuse15 sudo:    uyuni : (command continued) VlKE9QVElPTlMuc2FsdGRpcikK#012ICAgIGVsc2U6CiAgICAgICAgcmV0Y29kZSA9InByb2Nlc3MuY2FsbChzYWx0X2FyZ3YpCiAg#012ICBpZiBPUFRJT05TLmNtZF91bWFzayBpcyBub3QgTm9uZToKICAgICAgICBvcy51bWFzayhvbGRf#012dW1hc2spICAjIHB5bGludDogZGlzYWJsZT1ibGFja2xpc3RlZC1mdW5jdGlvbgogICAgcmV0dXJu#012IHJldGNvZGUKCgppZiBfX25hbWVfXyA9PSAiX19tYWluX18iOgogICAgc3lzLmV4aXQobWFpbihz#012eXMuYXJndikpCg==#012""").decode("utf-8"))
2022-03-10T11:52:36.868672+01:00 opensuse15 sudo: pam_unix(sudo:session): session opened for user root by (uid=10001)
2022-03-10T11:52:37.882067+01:00 opensuse15 sudo: pam_unix(sudo:session): session closed for user root
2022-03-10T11:52:37.898639+01:00 opensuse15 sshd[29051]: Received disconnect from 10.X.X.1 port 60588:11: disconnected by user
2022-03-10T11:52:37.898933+01:00 opensuse15 systemd[1]: session-87.scope: Succeeded.
2022-03-10T11:52:37.899005+01:00 opensuse15 sshd[29051]: Disconnected from user uyuni 10.X.X.1 port 60588
2022-03-10T11:52:37.899108+01:00 opensuse15 sshd[29048]: pam_unix(sshd:session): session closed for user uyuni
2022-03-10T11:52:37.900538+01:00 opensuse15 systemd-logind[1084]: Session 87 logged out. Waiting for processes to exit.
2022-03-10T11:52:37.901436+01:00 opensuse15 systemd-logind[1084]: Removed session 87.
2022-03-10T11:52:38.669355+01:00 opensuse15 sshd[29091]: Accepted keyboard-interactive/pam for uyuni from 10.X.X.1 port 60590 ssh2
2022-03-10T11:52:38.684693+01:00 opensuse15 systemd-logind[1084]: New session 88 of user uyuni.
2022-03-10T11:52:38.686030+01:00 opensuse15 systemd[1]: Started Session 88 of user uyuni.
2022-03-10T11:52:38.702071+01:00 opensuse15 sshd[29091]: pam_unix(sshd:session): session opened for user uyuni by (uid=0)
2022-03-10T11:52:38.907827+01:00 opensuse15 sshd[29094]: Received disconnect from 10.X.X.1 port 60590:11: disconnected by user
2022-03-10T11:52:38.911591+01:00 opensuse15 sshd[29094]: Disconnected from user uyuni 10.X.X.1 port 60590
2022-03-10T11:52:38.917070+01:00 opensuse15 sshd[29091]: pam_unix(sshd:session): session closed for user uyuni
2022-03-10T11:52:38.917720+01:00 opensuse15 systemd[1]: session-88.scope: Succeeded.
2022-03-10T11:52:38.921426+01:00 opensuse15 systemd-logind[1084]: Session 88 logged out. Waiting for processes to exit.
2022-03-10T11:52:38.924356+01:00 opensuse15 systemd-logind[1084]: Removed session 88.
2022-03-10T11:52:39.480821+01:00 opensuse15 sshd[29121]: pam_tally2(sshd:auth): user uyuni (10001) tally 7, deny 6
2022-03-10T11:52:40.953158+01:00 opensuse15 sshd[29119]: error: PAM: Authentication failure for uyuni from 10.X.X.1
2022-03-10T11:52:40.969022+01:00 opensuse15 sshd[29122]: pam_tally2(sshd:auth): user uyuni (10001) tally 8, deny 6
2022-03-10T11:52:42.253570+01:00 opensuse15 sshd[29119]: error: PAM: Authentication failure for uyuni from 10.X.X.1
2022-03-10T11:52:42.268969+01:00 opensuse15 sshd[29123]: pam_tally2(sshd:auth): user uyuni (10001) tally 9, deny 6
2022-03-10T11:52:42.275946+01:00 opensuse15 sshd[29119]: Postponed keyboard-interactive for uyuni from 10.X.X.1 port 60592 ssh2 [preauth]
2022-03-10T11:52:44.822036+01:00 opensuse15 sshd[29119]: error: PAM: Authentication failure for uyuni from 10.X.X.1108
2022-03-10T11:52:44.840465+01:00 opensuse15 sshd[29119]: Connection closed by authenticating user uyuni 10.X.X.1 port 60592 [preauth]
2022-03-10T11:52:49.004903+01:00 opensuse15 systemd[1]: Stopping User Manager for UID 10001...

Indeed in the client:

root@uyuni05v : /var/log # pam_tally2 -u uyuni
Login           Failures Latest failure     From
uyuni               9    03/10/22 11:52:42  10.X.X.X

[phibid]

Can't reproduce this issue again, will close this issue.

[phibid]

I re-open this issue because indeed, if pam_tally2 is activated, the ssh user used to bootstrap a new Uyuni client is locked, and the bootstraping failed to successfully finish.

[vzhestkov]

@phibid salt ssh is using pre flight script now to deploy the salt bundle and to push the script to the client and run it salt it opening extra ssh connections. It's not really possible to avoid this issue with any basic solution with no redesign of salt ssh subsystem. Maybe better to adjust the limit with deny=n for pam_tally2 to make it possible for salt ssh to work with it.

[meaksh]

Maybe we can add a note in our documentation about being careful with the usage of pam_tally2 as salt-ssh needs to create several connections at the same time to the bootstrapping system.

[vzhestkov]

@phibid I just found that the issue most probably related to misconfigured pam_tally2 when it counts successful login authentication attempts as failing ones, could you please check: https://www.suse.com/support/kb/doc/?id=000018034

[meaksh]

@phibid any chance to double check this?

[meaksh]

At this point I'm closing this issue as it seems this is caused by misconfigured pam_tally2, as mentioned in the previous comment.

@phibid feel free to reopen this issue again if you consider this is still relevant!

Thanks for contributing!

[phibid]

@meaksh Sorry for the delay ! I have checked your link, and I confirm that pam_tally2 was not correctly configured !

Thanks !