[SOLVED] Dovecot loads of ' PAM unable to dlopen...' messages

lpwevers · 10-03-2023, 07:21 AM

Hi,

On my server (openSUSE 15.5) I've been running a mailserver with dovecot happily for some time. Only, since the past few days I'm experiencing issues with dovecot. It starts up nicely and then I can use it for some time. But after that I can see that the logging is filling with loads of messages like this:

Code:

Oct 03 14:15:37 nami auth[10463]: pam_unix(dovecot:auth): check pass; user unknown
Oct 03 14:15:37 nami auth[10463]: pam_unix(dovecot:auth): authentication failure; logname= uid=0 euid=0 tty=dovecot ruser=abe rhost=46.148.40.151
Oct 03 14:15:41 nami auth[10463]: PAM unable to dlopen(/lib64/security/pam_unix.so): libnsl.so.2: failed to map segment from shared object
Oct 03 14:15:41 nami auth[10463]: PAM adding faulty module: /lib64/security/pam_unix.so
Oct 03 14:15:41 nami auth[10463]: PAM unable to dlopen(/lib64/security/pam_cracklib.so): libcrack.so.2: failed to map segment from shared object
Oct 03 14:15:41 nami auth[10463]: PAM adding faulty module: /lib64/security/pam_cracklib.so
Oct 03 14:15:41 nami auth[10463]: PAM unable to dlopen(/lib64/security/pam_systemd.so): libpam_misc.so.0: failed to map segment from shared object
Oct 03 14:15:41 nami auth[10463]: PAM adding faulty module: /lib64/security/pam_systemd.so
Oct 03 14:15:41 nami auth[10463]: PAM unable to dlopen(/lib64/security/pam_umask.so): /lib64/security/pam_umask.so: failed to map segment from shared object
Oct 03 14:15:41 nami auth[10463]: PAM adding faulty module: /lib64/security/pam_umask.so
Oct 03 14:15:41 nami auth[10463]: PAM unable to dlopen(/lib64/security/pam_warn.so): /lib64/security/pam_warn.so: failed to map segment from shared object
Oct 03 14:15:41 nami auth[10463]: PAM adding faulty module: /lib64/security/pam_warn.so
Oct 03 14:15:41 nami auth[10463]: PAM unable to dlopen(/lib64/security/pam_deny.so): /lib64/security/pam_deny.so: failed to map segment from shared object
Oct 03 14:15:41 nami auth[10463]: PAM adding faulty module: /lib64/security/pam_deny.so
Oct 03 14:15:43 nami auth[10463]: PAM unable to dlopen(/lib64/security/pam_unix.so): /lib64/security/pam_unix.so: failed to map segment from shared object
Oct 03 14:15:43 nami auth[10463]: PAM adding faulty module: /lib64/security/pam_unix.so

And after that, the only thing I can do is restart dovecot to get things working again. It's now so bad that I have a cron-job that restarts it every two minutes to have something that's at lease somewhat workable.

There have been no big changes on the server for some time now, only the installation of security fixes. (And I did roll them back without result).

Any idea what can be causing this? This is becoming quite annoying.

scasey · 10-04-2023, 02:09 AM

The rhost (remote host) of 46.148.40.151 is in Iran. grep the log file for the ‘authentication failure’ lines to see if they all have the same IP or if it’s a DDoS attack. That one example looks like a cracking attempt, especially if you don’t have any email users in Iran.

I don’t know why an invalid user failure would cause those PAM errors, but it’s my opinion that those failures are caused by the cracking attempt. Restarting dovecot would disconnect the abuser and “clear up” the problem.

Run

Code:

netstat -tnp

while the failures are happening to see who’s connected to your dovecot server…see if there’s a correlation with the IP addresses from the log. See what programs they are running. (Should be dovecot)

See if you can cause the problem by trying to log in to the dovecot server as an unknown user.

Mayhaps someone with PAM knowledge will help with that troubleshooting. On my dovecot serve such attempts just fail.

Code:

Oct 02 01:41:08 auth-worker(31290): Info: pam(baduser,1.55.219.163,<Z/U6vLcGIM8BN9uj>): unknown user
Oct 02 01:41:08 auth: Info: checkpassword(baduser,1.55.219.163,<Z/U6vLcGIM8BN9uj>): Login failed (status=1)
Oct 02 01:41:11 imap-login: Info: Disconnected (auth failed, 1 attempts in 4 secs): user=<baduser>, method=PLAIN, rip=1.55.219.163, lip=xxx.xx.xx.xx, session=<Z/U6vLcGIM8BN9uj>

lpwevers · 10-04-2023, 05:06 AM

Looks like you hit the spot with that one. There's continious authentication failures from various adresses in the 46.148.0.0/16 range. I know it's a bit drastic, but for now I've blocked that whole range in the firewall. It's now a lot quieter on that side. PAM errors a no longer occuring. Though I still believe that the server should not crash under the load.

baltic · 10-05-2023, 11:12 AM

FWIW: I see the same behavior on my own dovecot server. No attacks from Iran - but use of iOS devices in my own network triggers this. The client in this case misleadingly reports that there is no password set for the account. Restarting dovecot fixes the issue. Sometimes it starts to work again after a few minutes all by itself.

I assume that this instability was introduced by an update a couple of days ago - I never encountered this before.

lpwevers · 10-05-2023, 12:04 PM

That very much seems to be the case. If I use the server carefully it will keep on working, since I've blocked the Iranian IP addresses. But if, for instance, I connect using Roundcube webmail, dovecot breaks in a few moments. Roundcube seems to do a lot more IMAP requests than Thunderbird. Hopefully this will be fixed soon.

jsaathof · 10-06-2023, 02:10 PM

I have exacly the same issue. I don't know since when but I noticed it due to authentication errors in Snappymail. I am also using dovecot on openSUSE Leap 15.5. I don't know since when. I have not seen or experienced this issue for a long time. I first noticed this last week. I have searched for this issue and found no solution but also not the _exact same issue_ until I found this post.

I have found dlopen errors where the solution offerred had something to do with limits. I can imagine this since my server is running quite some applications (Nextcloud, gitlab, grafana, Icinga, and dovecot to name a few). Maybe we should look in this direction.

lpwevers · 10-06-2023, 04:20 PM

I found this somewhere, but it didn't seem to help. I added this to /etc/security/limits.conf

* soft memlock unlimited
* hard memlock unlimited

But that doesn't seem to help. When logged in as a normal user, max locked memory is still 64k. As root it's unlimited. Seems like an issue with pam, but I lack the knowledge of that. Server of mine is also running loads of stuff, but this was never an issue until recent.

jsaathof · 10-07-2023, 04:04 AM

Maybe the fact that the ulimit changes don't work is because of systemd. There is a different way to set the limits in systemd. I had found this https://www.freedesktop.org/software...html#LimitCPU=. But I have tried to set the LimitMEMLOCK to infinity for the dovecot process but that did not help either.

I doubt it is a PAM issue since PAM is working correctly on other machines and even on this machine. Even for dovecot, at least for a brief moment. So to me this means that the issue is not in some specific library. And I have looked at other VMs I have running. They don't show this issue. The intermittent charachter makes this issue hard to figure out.

But the other errors I found on the internet for the dlopen error showed extra information. like "permission denied" or "unable to allocate memory". This just shows it cannot map the segment. No extra information is provided on why. This is probably somewhere in the dlopen code which I assume is part of the glibc code. However I have not much experience with this either.

jsaathof · 10-07-2023, 06:13 AM

I think I have found a way to work around this. I have enabled the auth caching in dovecot. Bear in mind the following pathnames are for openSUSE (Leap 15.5). On other distros they may be in other files I guess.

In 10-auth.conf:

Code:

auth_cache_size = 10M
auth_cache_ttl = 1 hour
auth_cache_negative_ttl = 0

The comments show that for PAM authentication an auth_key needs to be set.

In auth-system.conf.ext change:

Code:

passdb {
  driver = pam
  # [session=yes] [setcred=yes] [failure_show_msg=yes] [max_requests=<n>]
  # [cache_key=<key>] [<service name>]
  args = cache_key=%u                                                      <== Add/change this
}

Now I cannot reproduce the errors. I was able to reproduce this by quickly changing IMAP folders in my webmail (Snappymail). Now I can click all I want but it will always load.

Maybe there is some sort of mechanism that prevents a lot of requests for PAM. I noticed before that I did not have to restart dovecot to get things working again. Waiting for a minute or so would also allow the webmail to work again as well. Is the webmail app DOS-ing PAM maybe?

lpwevers · 10-09-2023, 01:52 AM

Thank you @jsaathof. This workaround does magic. I'm no longer able to reproduce the issue now.

baltic · 10-09-2023, 09:55 AM

@jsaathof: Thank you so much - this worked for me as well!

Lerrissirrel · 10-09-2023, 08:18 PM

Thank you! This was driving me nuts. It took me days to run across this thread.

In the hope that it will help others find it, a few addition "keywords"
- This first happened to me on opensuse 15.4 (I upgraded to 15.5 in the hope it would help, obviously it didn't)
- Got "PAM adding faulty module:" as well as "PAM unable to dlopen" in /var/log/messages
- Got "pam_authenticate() failed: Module is unknown" in dovecot logs

lpwevers · 10-10-2023, 08:38 AM

Yes, @lerrissirrel, sounds like exactly what I did. I was on 15.4 as well, then went to 15.5 to see if that fixed the issue etc. Though I must add one more thing. With this work-around in place, indeed dovecot now works as it should even when "under stress" from Roundcube. But....

I decided to see if my original issue was solved with this as well, so I allowed the Iranian IP range again in my firewall. Within 5 minutues the "PAM adding faulty module:" as well as "PAM unable to dlopen" started popping up again. So I guess the caching only works for valid logins (which is quite logical when you think about it). But the server being under stress from invalid logins still breaks things.

Sportsman · 10-10-2023, 12:44 PM

Hi.

The PAM — Dovecot documentation states the following:
"Usually in other software PAM is used to do only a single lookup in a process, so PAM plugin writers haven’t done much testing on what happens when multiple lookups are done. Because of this, many PAM plugins leak memory and possibly have some other problems when doing multiple lookups. If you notice that PAM authentication stops working after some time, you can limit the number of lookups done by the auth worker process before it dies".

So I think a more correct solution is to "Limiting the number of PAM lookups" rather than "Caching".

My auth-system.conf.ext configuration looks like this:

Code:

passdb {
  driver = pam
  # [session=yes] [setcred=yes] [failure_show_msg=yes] [max_requests=<n>]
  # [cache_key=<key>] [<service name>]
  args = max_requests=1
}

Lerrissirrel · 10-10-2023, 04:54 PM

Quote:

Originally Posted by Sportsman

So I think a more correct solution is to "Limiting the number of PAM lookups" rather than "Caching".

My auth-system.conf.ext configuration looks like this:

Code:

passdb {
  driver = pam
  # [session=yes] [setcred=yes] [failure_show_msg=yes] [max_requests=<n>]
  # [cache_key=<key>] [<service name>]
  args = max_requests=1
}

Yeah, I knew it was only a workaround at best. I was trying to avoid getting tagged to file a bug report! Interesting note in the dovecot documentation. Odd that something in a recent opensuse package update (that wasn't dovecot or pam) triggered this behavior.

I removed the caching change, recreated the issue, made the max_requests change and so far so good. Thanks for a better answer!

Regards,
L