Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-24535

pam v2: Authentication fails randomly

Details

    Description

      I'm running several webapps (PHP) on a CentOS 8 webserver. All webapps are reporting randomly that the connection to the database has been denied.

      The "authentication chain" looks like this:
      webapp => mariadb => pam v2 plugin => sssd => ldap

      Switching to the "old" pam v1 plugin fixes this issue.

      I'm sorry, I can't provide much information, let me know if you have further ideas where to look at. So far I only noticed the following lines in the sssd_pam.log on affected systems:

      (2021-01-06 11:25:01): [pam] [client_send] (0x0010): Failed to send data, aborting client!
      (2021-01-06 11:25:01): [pam] [client_send] (0x0010): Failed to send data, aborting client!
      (2021-01-06 11:25:12): [pam] [client_send] (0x0010): Failed to send data, aborting client!
      (2021-01-06 11:25:12): [pam] [client_send] (0x0010): Failed to send data, aborting client!
      (2021-01-06 11:25:16): [pam] [client_send] (0x0010): Failed to send data, aborting client!
      (2021-01-06 11:25:40): [pam] [client_send] (0x0010): Failed to send data, aborting client!
      

      Mariadb:

      Jan 06 11:25:01 <hostname> mysqld[1389]: 2021-01-06 11:25:01 60141 [Warning] Access denied for user '<username1>'@'localhost' (using password: NO)
      Jan 06 11:25:01 <hostname> mysqld[1389]: 2021-01-06 11:25:01 60140 [Warning] Access denied for user '<username1>'@'localhost' (using password: NO)
      Jan 06 11:25:12 <hostname> mysqld[1389]: 2021-01-06 11:25:12 60167 [Warning] Access denied for user '<username2>'@'localhost' (using password: NO)
      Jan 06 11:25:12 <hostname> mysqld[1389]: 2021-01-06 11:25:12 60168 [Warning] Access denied for user '<username2>'@'localhost' (using password: NO)
      Jan 06 11:25:16 <hostname> mysqld[1389]: 2021-01-06 11:25:16 60180 [Warning] Access denied for user '<username3>'@'localhost' (using password: NO)
      Jan 06 11:25:40 <hostname> mysqld[1389]: 2021-01-06 11:25:40 60236 [Warning] Access denied for user '<username3>'@'localhost' (using password: NO)
      

      Attachments

        Activity

          Hello, Florian!
          I couldn't understand the cause of the problem from just that data.
          Is it possible for you to rund the debug version of the auth_pam plugin with the --pam-debug=ON?
          And then send the mariadb's log.
          That could be really helpful.

          Regards.
          HF

          holyfoot Alexey Botchkov added a comment - Hello, Florian! I couldn't understand the cause of the problem from just that data. Is it possible for you to rund the debug version of the auth_pam plugin with the --pam-debug=ON? And then send the mariadb's log. That could be really helpful. Regards. HF

          Sorry for the delay, too many things to solve...

          I couldn't understand the cause of the problem from just that data.

          That was expected on my side

          Is it possible for you to rund the debug version of the auth_pam plugin with the --pam-debug=ON?

          Is there an debug package available somewhere? Otherwise detailed information on how to build the debug version would be required.

          fbezdeka Florian Bezdeka added a comment - Sorry for the delay, too many things to solve... I couldn't understand the cause of the problem from just that data. That was expected on my side Is it possible for you to rund the debug version of the auth_pam plugin with the --pam-debug=ON? Is there an debug package available somewhere? Otherwise detailed information on how to build the debug version would be required.
          vklasen Volker Klasen added a comment -

          We have the same issue with PAM authentication. We're using PAM with SSSD and LDAP to authenticate (non-application) users.

          Only on some databases this is an issue that we can more or less consistently reproduce. A Restart of the database fixes the issue for a while. There are no hints in the log files, neither MariaDB's nor SSSD's. It looks as if MariaDB just would not use PAM at some point anymore.

          We don't have debug logs, but with more detailed information, I guess, we could provide them.

          Cheers,
          Volker

          vklasen Volker Klasen added a comment - We have the same issue with PAM authentication. We're using PAM with SSSD and LDAP to authenticate (non-application) users. Only on some databases this is an issue that we can more or less consistently reproduce. A Restart of the database fixes the issue for a while. There are no hints in the log files, neither MariaDB's nor SSSD's. It looks as if MariaDB just would not use PAM at some point anymore. We don't have debug logs, but with more detailed information, I guess, we could provide them. Cheers, Volker
          vklasen Volker Klasen added a comment -

          I was able to build a debug version of the auth_pam Plugin and could reproduce the issue.

          Working authentication (mysql-error.log):

          PAM: opening pipes.
          PAM: forking.
          PAM: parent continues.
          PAM: Child process prepares pipes.
          PAM: check tool directory: /opt/mysql/lib/plugin/, auth_pam_tool_dir/auth_pam_tool.
          PAM: execute pam sandbox [/opt/mysql/lib/plugin/auth_pam_tool_dir/auth_pam_tool].
          PAM: parent sends user data [vklasen], [].
          PAM: listening to the sandbox.
          Got error 1 from setreuid()
          PAM: getting CONV string.
          PAM: answering CONV.
          PAM: listening to the sandbox.
          PAM: reading authenticated_as string.
          PAM: listening to the sandbox.
          PAM: auth OK returned.
          PAM: auth result -1.
          

          After some time it does not anymore:

          PAM: opening pipes.
          PAM: forking.
          PAM: auth result 0.
          2021-04-15  8:49:30 571 [Warning] Access denied for user 'vklasen'@'workstation.workplace.tld' (using password: NO)
          

          I hope that helps in finding the cause.

          Cheers,
          Volker

          vklasen Volker Klasen added a comment - I was able to build a debug version of the auth_pam Plugin and could reproduce the issue. Working authentication (mysql-error.log): PAM: opening pipes. PAM: forking. PAM: parent continues. PAM: Child process prepares pipes. PAM: check tool directory: /opt/mysql/lib/plugin/, auth_pam_tool_dir/auth_pam_tool. PAM: execute pam sandbox [/opt/mysql/lib/plugin/auth_pam_tool_dir/auth_pam_tool]. PAM: parent sends user data [vklasen], []. PAM: listening to the sandbox. Got error 1 from setreuid() PAM: getting CONV string. PAM: answering CONV. PAM: listening to the sandbox. PAM: reading authenticated_as string. PAM: listening to the sandbox. PAM: auth OK returned. PAM: auth result -1. After some time it does not anymore: PAM: opening pipes. PAM: forking. PAM: auth result 0. 2021-04-15 8:49:30 571 [Warning] Access denied for user 'vklasen'@'workstation.workplace.tld' (using password: NO) I hope that helps in finding the cause. Cheers, Volker
          vklasen Volker Klasen added a comment -

          fork() fails with ENOMEM:

          PAM: opening pipes.
          PAM: forking.
          PAM: fork failed: Cannot allocate memory
          PAM: auth result 0.
          

          Memory should be enough available (though mysqld has a VIRT memory usage of 26.7g):

          user@host ~> free -m
                        total        used        free      shared  buff/cache   available
          Mem:          32166        7767       23609         336         789       23684
          Swap:             0           0           0
          

          It looks like the same issue as in https://bugs.launchpad.net/percona-server/+bug/1520267 (https://jira.percona.com/browse/PS-3332).

          Cheers,
          Volker

          vklasen Volker Klasen added a comment - fork() fails with ENOMEM: PAM: opening pipes. PAM: forking. PAM: fork failed: Cannot allocate memory PAM: auth result 0. Memory should be enough available (though mysqld has a VIRT memory usage of 26.7g): user@host ~> free -m total used free shared buff/cache available Mem: 32166 7767 23609 336 789 23684 Swap: 0 0 0 It looks like the same issue as in https://bugs.launchpad.net/percona-server/+bug/1520267 ( https://jira.percona.com/browse/PS-3332 ). Cheers, Volker
          vklasen Volker Klasen added a comment -

          I attached a patch that replaces fork() + exec() by posix_spawn() with which I could no longer reproduce the bug and could login via PAM even when the server process used more than 50% of available RAM.
          However, as I am not very familiar with C, memory management and such, I cannot rule out side effects.

          I obviously forgot about this ticket and created MDEV-26212 as a duplicate, I only just found this one again.

          Cheers
          Volker

          vklasen Volker Klasen added a comment - I attached a patch that replaces fork() + exec() by posix_spawn() with which I could no longer reproduce the bug and could login via PAM even when the server process used more than 50% of available RAM. However, as I am not very familiar with C, memory management and such, I cannot rule out side effects. I obviously forgot about this ticket and created MDEV-26212 as a duplicate, I only just found this one again. Cheers Volker

          fbezdeka

          Is there an debug package available somewhere? Otherwise detailed information on how to build the debug version would be required.

          we don't build centos8 debug packages, but we have centos7 debug packages: http://hasky.askmonty.org/archive/10.4/build-48235/kvm-rpm-centos74-amd64-debug/rpms/

          otherwise you can build it yourself as described here: https://mariadb.com/kb/en/generic-build-instructions/
          just don't forget to specify -DCMAKE_BUILD_TYPE=Debug. You will also need to set pam-debug

          serg Sergei Golubchik added a comment - fbezdeka Is there an debug package available somewhere? Otherwise detailed information on how to build the debug version would be required. we don't build centos8 debug packages, but we have centos7 debug packages: http://hasky.askmonty.org/archive/10.4/build-48235/kvm-rpm-centos74-amd64-debug/rpms/ otherwise you can build it yourself as described here: https://mariadb.com/kb/en/generic-build-instructions/ just don't forget to specify -DCMAKE_BUILD_TYPE=Debug . You will also need to set pam-debug
          fbezdeka Florian Bezdeka added a comment - - edited

          My systems are no longer running CentOS 8. They have been migrated to Debian but the problem remained.

          I will now update some systems to 10.5.16 as this version has a fix for MDEV-26212. Let's see but maybe this issue here is a duplicate of MDEV-26212.

          fbezdeka Florian Bezdeka added a comment - - edited My systems are no longer running CentOS 8. They have been migrated to Debian but the problem remained. I will now update some systems to 10.5.16 as this version has a fix for MDEV-26212 . Let's see but maybe this issue here is a duplicate of MDEV-26212 .

          People

            holyfoot Alexey Botchkov
            fbezdeka Florian Bezdeka
            Votes:
            1 Vote for this issue
            Watchers:
            9 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Git Integration

                Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.