Mageia forum

In keeping with the recent habit of systemd reconfiguring my system upon updates, some critical logging has stopped since an update I made on 19 Dec, and I don't know how to fix it.

Specifically, for many many years I have received the following information in /var/log/auth.log:

Code: Select all

Dec 17 21:11:22 dadsbox sshd[29938]: pam_unix(sshd:auth): check pass; user unknown
Dec 17 21:11:22 dadsbox sshd[29938]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=51.77.147.5


For me, this is critical information because a monitor program I run depends on it. After 6 failed attempts to login, the IP address is blocked for one week.

These entries stopped arriving in auth.log on Dec 19, and I just noticed it. Does anyone here know how I can turn this logging back on?

What pam modules do you currently have that check user / password validity ? Something for chkpwd maybe? Also, what do the pam_unix lines look like ?

I have never messed with pam. Never had the need to. So my configuration should be full-stock.

The sshd file in /etc/pam.d contains:

Code: Select all

#%PAM-1.0
auth       required     pam_listfile.so item=user sense=deny file=/etc/ssh/denyusers
auth       include      system-auth
account    required     pam_nologin.so
account    include      system-auth
password   include      system-auth
session    include      system-auth


And the system-auth file contains:

Code: Select all

#%PAM-1.0

auth        required      pam_env.so
auth        sufficient    pam_unix.so try_first_pass likeauth nullok
auth        required      pam_deny.so

account     sufficient    pam_tcb.so shadow
account     required      pam_deny.so

password    required      pam_cracklib.so try_first_pass retry=3 minlen=4  dcredit=0  ucredit=0
password    sufficient    pam_unix.so try_first_pass use_authtok nullok sha512 shadow
password    required      pam_deny.so

session     optional      pam_keyinit.so revoke
session     required      pam_limits.so
session     [success=1 default=ignore] pam_succeed_if.so service in crond quiet use_uid
-session    optional      pam_systemd.so
session     required      pam_unix.so


None of the files in /lib/security or in /etc/pam.d show recent datestamps that might be useful. Also, none of these seem to indicate anything regarding logging. The syslog.conf file has not changed in years.

Well, if you look at the man page for pam_unix then you see that even without any options, invalid arguments (logins) should be logged. I though I remembered something that you need to enable some logging, but guess that's not the case.
You could enable debug for pam_unix and/or check if those logins are at least written to journal. To reproduce, simply ssh invaliduser@localhost, this should be the same as a regular login from the outside.

Does that appear in journal logs?

Logins are not appearing in the journal. There is a message in the journal from the kernel that a connection is made on port 22, and nothing follows.

Hmmm, that is interesting, I'll try to reproduce.

That issue is on an uptodate mga7 system, and sshd_config is also pretty default ?

Can't really reproduce here, logging is still working fine in my mga7 VM with all updates applied. pam and sshd_config is still the default.
One difference I spotted is my account section is different then yours in /etc/pam.d/system-auth - you only have pam_deny there.

[doktor5000@Mageia7VM ~]$ sudo cat /etc/pam.d/system-auth
#%PAM-1.0

auth required pam_env.so
auth sufficient pam_unix.so try_first_pass likeauth nullok
auth required pam_deny.so

account required pam_unix.so

password required pam_cracklib.so try_first_pass retry=3 minlen=4 dcredit=0 ucredit=0
password sufficient pam_unix.so try_first_pass use_authtok nullok sha512 shadow
password required pam_deny.so

session optional pam_keyinit.so revoke
session required pam_limits.so
session [success=1 default=ignore] pam_succeed_if.so service in crond quiet use_uid
-session optional pam_systemd.so
session required pam_unix.so

This is what an invalid login attempt looks like in journal logs:
(I don't have forwarding to syslog because I don't need that, but the pam_unix messages are in the logs, so they would be forwarded).

Code: Select all

Dec 25 11:07:50 Mageia7VM sudo[28046]: doktor5000 : TTY=pts/0 ; PWD=/home/doktor5000 ; USER=root ; COMMAND=/bin/systemctl start sshd
Dec 25 11:07:50 Mageia7VM systemd[1]: Condition check resulted in OpenSSH Server Key Generation being skipped.
Dec 25 11:07:57 Mageia7VM sshd[28065]: Invalid user invaliduser from ::1 port 36142
Dec 25 11:07:57 Mageia7VM sshd[28065]: Postponed keyboard-interactive for invalid user invaliduser from ::1 port 36142 ssh2 [preauth]
Dec 25 11:08:00 Mageia7VM sshd[28067]: pam_unix(sshd:auth): check pass; user unknown
Dec 25 11:08:00 Mageia7VM sshd[28067]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=::1
Dec 25 11:08:02 Mageia7VM sshd[28065]: error: PAM: Authentication failure for illegal user invaliduser from ::1
Dec 25 11:08:02 Mageia7VM sshd[28065]: Failed keyboard-interactive/pam for invalid user invaliduser from ::1 port 36142 ssh2
Dec 25 11:08:02 Mageia7VM sshd[28065]: Postponed keyboard-interactive for invalid user invaliduser from ::1 port 36142 ssh2 [preauth]
Dec 25 11:08:05 Mageia7VM sshd[28071]: pam_unix(sshd:auth): check pass; user unknown
Dec 25 11:08:05 Mageia7VM sshd[28071]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=::1
Dec 25 11:08:07 Mageia7VM sshd[28065]: error: PAM: Authentication failure for illegal user invaliduser from ::1
Dec 25 11:08:07 Mageia7VM sshd[28065]: Failed keyboard-interactive/pam for invalid user invaliduser from ::1 port 36142 ssh2
Dec 25 11:08:07 Mageia7VM sshd[28065]: Postponed keyboard-interactive for invalid user invaliduser from ::1 port 36142 ssh2 [preauth]
Dec 25 11:08:09 Mageia7VM sshd[28078]: pam_unix(sshd:auth): check pass; user unknown
Dec 25 11:08:09 Mageia7VM sshd[28078]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=::1
Dec 25 11:08:11 Mageia7VM sshd[28065]: error: PAM: Authentication failure for illegal user invaliduser from ::1
Dec 25 11:08:11 Mageia7VM sshd[28065]: Failed keyboard-interactive/pam for invalid user invaliduser from ::1 port 36142 ssh2
Dec 25 11:08:14 Mageia7VM sshd[28065]: pam_unix(sshd:auth): check pass; user unknown
Dec 25 11:08:14 Mageia7VM sshd[28065]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=::1
Dec 25 11:08:17 Mageia7VM sshd[28065]: Failed password for invalid user invaliduser from ::1 port 36142 ssh2
Dec 25 11:08:19 Mageia7VM sshd[28065]: Failed password for invalid user invaliduser from ::1 port 36142 ssh2
Dec 25 11:08:20 Mageia7VM sshd[28065]: Failed password for invalid user invaliduser from ::1 port 36142 ssh2
Dec 25 11:08:20 Mageia7VM sshd[28065]: error: maximum authentication attempts exceeded for invalid user invaliduser from ::1 port 36142 ssh2 [preauth]
Dec 25 11:08:20 Mageia7VM sshd[28065]: Disconnecting invalid user invaliduser ::1 port 36142: Too many authentication failures [preauth]
Dec 25 11:08:49 Mageia7VM sudo[31183]: doktor5000 : TTY=pts/0 ; PWD=/home/doktor5000 ; USER=root ; COMMAND=/bin/journalctl -ab

sshd_config still completely default:

Code: Select all

[doktor5000@Mageia7VM ~]$ sudo grep -vE "^#|^$" /etc/ssh/sshd_config
HostKey /etc/ssh/ssh_host_rsa_key
HostKey /etc/ssh/ssh_host_ecdsa_key
HostKey /etc/ssh/ssh_host_ed25519_key
AuthorizedKeysFile      .ssh/authorized_keys
UsePAM yes
AcceptEnv LANG LC_CTYPE LC_NUMERIC LC_TIME LC_COLLATE LC_MONETARY LC_MESSAGES
AcceptEnv LC_PAPER LC_NAME LC_ADDRESS LC_TELEPHONE LC_MEASUREMENT
AcceptEnv LC_IDENTIFICATION LC_ALL
X11Forwarding yes
Subsystem       sftp    /usr/libexec/openssh/sftp-server
PermitRootLogin without-password
[doktor5000@Mageia7VM ~]$

doktor5000 wrote:Hmmm, that is interesting, I'll try to reproduce.

That issue is on an uptodate mga7 system, and sshd_config is also pretty default ?

The issue appears to be related to the date of an update so I presume the update is responsible.

sshd_config is not default; it is old and has evolved over time as required. I last changed it in November as I was updating my config to disallow DSA authentication and to allow rsa, ecdsa, and ed25519 keys. No other changes in a long time, and logging worked for awhile after this change.

I had to reboot the system this morning. I was hoping that the reboot would return my logging, but no joy.

One difference I spotted is my account section is different then yours in /etc/pam.d/system-auth - you only have pam_deny there.


[doktor5000@Mageia7VM ~]$ sudo cat /etc/pam.d/system-auth
#%PAM-1.0

auth required pam_env.so
auth sufficient pam_unix.so try_first_pass likeauth nullok
auth required pam_deny.so

account required pam_unix.so

password required pam_cracklib.so try_first_pass retry=3 minlen=4 dcredit=0 ucredit=0
password sufficient pam_unix.so try_first_pass use_authtok nullok sha512 shadow
password required pam_deny.so

session optional pam_keyinit.so revoke
session required pam_limits.so
session [success=1 default=ignore] pam_succeed_if.so service in crond quiet use_uid
-session optional pam_systemd.so
session required pam_unix.so

There is a file in my /etc/pam.d directory titled system-auth.rpmnew and when I diff it with the running system-auth file, I see that it matches yours. It could be that some systemd update has made the newer configuration mandatory. So I have swapped the files so that the rpmnew file is in use, restarted saslauthd, and I will see what happens.

...aaannnnddddd...no.

That did not fix it.

I have changed the logging level in sshd_config to VERBOSE, and now I see that successful logins are being reported, but failed ones are not (and it is the failed ones that are most important to me).

Specifically, I can log in with my phone and get many lines of information about the process. As I look back through the logs, this has been the case but I did not notice it before.

So, now I need to figure out why errors are not reported while successes are.

My logging returned to life, all by itself, on the 13th a bit after 3PM and I just noticed it.

I have no idea why. No updates were performed on that date. No reboots. No nothing.

But logging of ssh attempts resumed.

It turns out that my logging has returned...sometimes.

It appears that I get logging for a few minutes to a few hours, then it stops again for some indefinite period.

This is more than a bit aggravating.