DovecotでSSL接続をしたいが[AUTH] Authentication failed.で弾かれてしまう（pam認証、PLAIN）

実現したいこと

CentOS Stream9 + Postfix + Dovecotを用いたメールサーバーに対して、他のメーラー（Gmail）でログインしようとしています。
最初に接続だけ確認したいのでパスワードを暗号化することなく、pam認証と平文のPLAINでログインしようと考えております。

発生している問題・分からないこと

※独自ドメイン名を「domain.com」、CentOSアカウント名「hoge」、パスワードを「PSWD」と表示させて頂きます。
※メールの送受信に関しては問題なく実現できており、DHパラメーターも追加しています。

openssl s_client -connect domain.com:995を入力後、「USER user」入力は通るのに「PASS pswd」入力で[AUTH] Authentication failed.が表示されて弾かれてしまいます。
telnet localhost 110でも同様にPASSの入力後に同じエラーで弾かれてしまいました。

dovecotを起動～接続終了部分のログを以下に添付いたしました。
また、実行したコマンドも同様に添付しました。
どうして認証に失敗してしまうのか、ご存じの方がいらっしゃいましたらご教授のほどよろしくお願いいたします。

該当のソースコード

maillog(openssl)
1Jul 25 07:49:21 auth: Debug: auth client connected (pid=27567)
2Jul 25 07:49:32 auth: Debug: client in: AUTH	1	PLAIN	service=pop3	secured=tls	session=vV92FwYePuug++fV	lip=160.251.231.213	rip=160.251.231.213	lport=995	rport=60222	local_name=domain.com	resp=AGFtYW1pc2RyZWFtAFNpc3lhbW85 (previous base64 data may contain sensitive data)
3Jul 25 07:49:32 auth: Debug: pam(hoge,160.251.231.213,<vV92FwYePuug++fV>): Performing passdb lookup
4Jul 25 07:49:32 auth-worker(27570): Debug: Loading modules from directory: /usr/lib64/dovecot/auth
5Jul 25 07:49:32 auth-worker(27570): Debug: Module loaded: /usr/lib64/dovecot/auth/lib20_auth_var_expand_crypt.so
6Jul 25 07:49:32 auth-worker(27570): Debug: Module loaded: /usr/lib64/dovecot/auth/libdriver_sqlite.so
7Jul 25 07:49:32 auth-worker(27570): Debug: conn unix:auth-worker (pid=27569,uid=97): Server accepted connection (fd=13)
8Jul 25 07:49:32 auth-worker(27570): Debug: conn unix:auth-worker (pid=27569,uid=97): Sending version handshake
9Jul 25 07:49:32 auth-worker(27570): Debug: conn unix:auth-worker (pid=27569,uid=97): auth-worker<1>: Handling PASSV request
10Jul 25 07:49:32 auth-worker(27570): Debug: conn unix:auth-worker (pid=27569,uid=97): auth-worker<1>: pam(hoge,160.251.231.213,<vV92FwYePuug++fV>): Performing passdb lookup
11Jul 25 07:49:32 auth-worker(27570): Debug: conn unix:auth-worker (pid=27569,uid=97): auth-worker<1>: pam(hoge,160.251.231.213,<vV92FwYePuug++fV>): lookup service=dovecot
12Jul 25 07:49:32 auth-worker(27570): Debug: conn unix:auth-worker (pid=27569,uid=97): auth-worker<1>: pam(hoge,160.251.231.213,<vV92FwYePuug++fV>): #1/1 style=1 msg=Password: 
13Jul 25 07:49:34 auth-worker(27570): Info: conn unix:auth-worker (pid=27569,uid=97): auth-worker<1>: pam(hoge,160.251.231.213,<vV92FwYePuug++fV>): pam_authenticate() failed: Authentication failure (Password mismatch?) (given password: PSWD)
14Jul 25 07:49:34 auth: Debug: pam(hoge,160.251.231.213,<vV92FwYePuug++fV>): Finished passdb lookup
15Jul 25 07:49:34 auth: Debug: auth(hoge,160.251.231.213,<vV92FwYePuug++fV>): Auth request finished
16Jul 25 07:49:34 auth-worker(27570): Debug: conn unix:auth-worker (pid=27569,uid=97): auth-worker<1>: pam(hoge,160.251.231.213,<vV92FwYePuug++fV>): Finished passdb lookup
17Jul 25 07:49:34 auth-worker(27570): Debug: conn unix:auth-worker (pid=27569,uid=97): auth-worker<1>: Finished: password_mismatch
18Jul 25 07:49:36 auth: Debug: client passdb out: FAIL	1	user=hoge
19Jul 25 07:49:38 pop3-login: Info: Disconnected: Aborted login by logging out (auth failed, 1 attempts in 6 secs): user=<hoge>, method=PLAIN, rip=160.251.231.213, lip=160.251.231.213, TLS, TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)
20Jul 25 07:49:38 pop3-login: Debug: SSL alert: close notify
21Jul 25 07:50:32 auth-worker(27570): Debug: conn unix:auth-worker (pid=27569,uid=97): Disconnected: Connection closed (fd=-1)
22

maillog(telnet)
1Jul 25 07:59:57 hoge postfix/smtpd[27705]: connect from localhost[::1]
2Jul 25 08:00:43 hoge postfix/smtpd[27705]: disconnect from localhost[::1] quit=1 unknown=0/2 commands=1/3
3Jul 25 08:00:47 auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth
4Jul 25 08:00:47 auth: Debug: Module loaded: /usr/lib64/dovecot/auth/lib20_auth_var_expand_crypt.so
5Jul 25 08:00:47 auth: Debug: Module loaded: /usr/lib64/dovecot/auth/libdriver_sqlite.so
6Jul 25 08:00:47 auth: Debug: Read auth token secret from /run/dovecot/auth-token-secret.dat
7Jul 25 08:00:47 auth: Debug: auth client connected (pid=27720)
8Jul 25 08:00:55 auth: Debug: client in: AUTH	1	PLAIN	service=pop3	secured	session=F3kxQAYe3LAAAAAAAAAAAAAAAAAAAAAB	lip=::1	rip=::1	lport=110	rport=45276	resp=AGFtYW1pc2RyZWFtAFNpc3lhbW85 (previous base64 data may contain sensitive data)
9Jul 25 08:00:55 auth: Debug: pam(hoge,::1,<F3kxQAYe3LAAAAAAAAAAAAAAAAAAAAAB>): Performing passdb lookup
10Jul 25 08:00:55 auth-worker(27722): Debug: Loading modules from directory: /usr/lib64/dovecot/auth
11Jul 25 08:00:55 auth-worker(27722): Debug: Module loaded: /usr/lib64/dovecot/auth/lib20_auth_var_expand_crypt.so
12Jul 25 08:00:55 auth-worker(27722): Debug: Module loaded: /usr/lib64/dovecot/auth/libdriver_sqlite.so
13Jul 25 08:00:55 auth-worker(27722): Debug: conn unix:auth-worker (pid=27721,uid=97): Server accepted connection (fd=13)
14Jul 25 08:00:55 auth-worker(27722): Debug: conn unix:auth-worker (pid=27721,uid=97): Sending version handshake
15Jul 25 08:00:55 auth-worker(27722): Debug: conn unix:auth-worker (pid=27721,uid=97): auth-worker<1>: Handling PASSV request
16Jul 25 08:00:55 auth-worker(27722): Debug: conn unix:auth-worker (pid=27721,uid=97): auth-worker<1>: pam(hoge,::1,<F3kxQAYe3LAAAAAAAAAAAAAAAAAAAAAB>): Performing passdb lookup
17Jul 25 08:00:55 auth-worker(27722): Debug: conn unix:auth-worker (pid=27721,uid=97): auth-worker<1>: pam(hoge,::1,<F3kxQAYe3LAAAAAAAAAAAAAAAAAAAAAB>): lookup service=dovecot
18Jul 25 08:00:55 auth-worker(27722): Debug: conn unix:auth-worker (pid=27721,uid=97): auth-worker<1>: pam(hoge,::1,<F3kxQAYe3LAAAAAAAAAAAAAAAAAAAAAB>): #1/1 style=1 msg=Password: 
19Jul 25 08:00:57 auth-worker(27722): Info: conn unix:auth-worker (pid=27721,uid=97): auth-worker<1>: pam(hoge,::1,<F3kxQAYe3LAAAAAAAAAAAAAAAAAAAAAB>): pam_authenticate() failed: Authentication failure (Password mismatch?) (given password: PSWD)
20Jul 25 08:00:57 auth: Debug: pam(hoge,::1,<F3kxQAYe3LAAAAAAAAAAAAAAAAAAAAAB>): Finished passdb lookup
21Jul 25 08:00:57 auth: Debug: auth(hoge,::1,<F3kxQAYe3LAAAAAAAAAAAAAAAAAAAAAB>): Auth request finished
22Jul 25 08:00:57 auth-worker(27722): Debug: conn unix:auth-worker (pid=27721,uid=97): auth-worker<1>: pam(hoge,::1,<F3kxQAYe3LAAAAAAAAAAAAAAAAAAAAAB>): Finished passdb lookup
23Jul 25 08:00:57 auth-worker(27722): Debug: conn unix:auth-worker (pid=27721,uid=97): auth-worker<1>: Finished: password_mismatch
24Jul 25 08:00:59 auth: Debug: client passdb out: FAIL	1	user=hoge
25

/etc/dovecot/conf.d/10-auth.conf
disable_plaintext_auth = no
auth_mechanisms = plain
!include auth-system.conf.ext

/etc/dovecot/conf.d/10-master.conf
service imap-login {
  inet_listener imap {
   port = 143
  }
  inet_listener imaps {
    port = 993
    ssl = yes
  }
}
service pop3-login {
  inet_listener pop3 {
    port = 110
  }
  inet_listener pop3s {
    port = 995
    ssl = yes
  }
}
service submission-login {
  inet_listener submission {
    port = 587
  }
}
service auth {
  unix_listener auth-userdb {
    mode = 0666
    user = postfix
    group = postfix
  }
}

/etc/dovecot/conf.d/10-ssl.conf
ssl = required
ssl_cert = </etc/letsencrypt/live/amamisdream.com/fullchain.pem
ssl_key = </etc/letsencrypt/live/amamisdream.com/privkey.pem
ssl_dh = </etc/dovecot/dh.pem
ssl_cipher_list = PROFILE=SYSTEM
ssl_prefer_server_ciphers = yes

/etc/dovecot/conf.d/auth-system.conf.ext
passdb {
  driver = pam
  # [session=yes] [setcred=yes] [failure_show_msg=yes] [max_requests=<n>]
  # [cache_key=<key>] [<service name>]
  # args = session=yes dovecot
}
userdb {
  # <doc/wiki/AuthDatabase.Passwd.txt>
  driver = passwd
  # [blocking=no]
  #args = 

  # Override fields from passwd
  #override_fields = home=/home/virtual/%u
}


/etc/passwd
root:x:0:0:root:/root:/bin/bash
・・・
hoge:x:1000:1000::/home/hoge:/bin/bash
info:x:1001:1001::/home/info:/bin/bash
noreply:x:1002:1002::/home/noreply:/bin/bash
customer:x:1003:1003::/home/customer:/bin/bash
・・・

opensslとtelnetのコマンド履歴
1# openssl s_client -connect domain.com:995
2CONNECTED(00000003)
3---
4Certificate chain
5～～～～～～～～～～～
6SSL認証情報なので省略
7～～～～～～～～～～～
8read R BLOCK
9+OK Dovecot ready.
10USER hoge
11+OK
12PASS PSWD
13-ERR [AUTH] Authentication failed.
14quit
15+OK Logging out
16closed
17
18# telnet localhost 110
19Trying ::1...
20Connected to localhost.
21Escape character is '^]'.
22+OK Dovecot ready.
23USER hoge
24+OK
25PASS PSWD
26-ERR [AUTH] Authentication failed.
27quit
28+OK Logging out
29

試したこと・調べたこと

teratailやGoogle等で検索した
ソースコードを自分なりに変更した
知人に聞いた
その他

上記の詳細・結果

同じような現象に見舞われている方が少なく解決にたどり着くことができませんでした。

補足

特になし

TaichiYanagiya

2024/07/25 08:39

"password_mismatch" なのでユーザー、パスワードが合っていないのでは？ /var/log/secure にも PAM のログが出ていると思うので、そちらも確認ください。

gusachan

2024/07/25 09:51

cyrus-sasl-plain をインストールしてみてはいかがでしょうか？

Eggpan

2024/07/25 10:44

/etc/pam.d/dovecot の内容も関わってくるので、追記されたほうが良いかと思います。

gusachan

2024/07/25 11:13

確認ですがユーザーhoge なら、USER hoge@domain.com ですよね？

pofuda

2024/07/25 12:40

>>/var/log/secure にも PAM のログが出ていると思うので、そちらも確認ください。以下がsystemctl restart rsyslogを打った後のログです。気づかなかったのですが、起動して二行目からログインに失敗しているみたいです…。 Jul 25 21:35:39 hoge sshd[35757]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=180.101.88.251 user=root Jul 25 21:35:41 hoge sshd[35757]: Failed password for root from 180.101.88.251 port 60157 ssh2 Jul 25 21:35:44 hoge sshd[35757]: Failed password for root from 180.101.88.251 port 60157 ssh2 Jul 25 21:35:46 hoge sshd[35757]: Failed password for root from 180.101.88.251 port 60157 ssh2 Jul 25 21:35:48 hoge sshd[35757]: Received disconnect from 180.101.88.251 port 60157:11: [preauth] Jul 25 21:35:48 hoge sshd[35757]: Disconnected from authenticating user root 180.101.88.251 port 60157 [preauth] Jul 25 21:35:48 hoge sshd[35757]: PAM 2 more authentication failures; logname= uid=0 euid=0 tty=ssh ruser= rhost=180.101.88.251 user=root Jul 25 21:36:25 hoge auth[35766]: pam_unix(dovecot:auth): authentication failure; logname= uid=0 euid=0 tty=dovecot ruser=hoge rhost=::1 user=hoge Jul 25 21:36:28 hoge auth[35766]: PAM 1 more authentication failure; logname= uid=0 euid=0 tty=dovecot ruser=hoge rhost=::1 user=hoge Jul 25 21:36:32 hoge sshd[35767]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=180.101.88.251 user=root Jul 25 21:36:35 hoge sshd[35767]: Failed password for root from 180.101.88.251 port 59014 ssh2 Jul 25 21:36:37 hoge sshd[35767]: Failed password for root from 180.101.88.251 port 59014 ssh2 Jul 25 21:36:40 hoge sshd[35767]: Failed password for root from 180.101.88.251 port 59014 ssh2 Jul 25 21:36:40 hoge sshd[35767]: Received disconnect from 180.101.88.251 port 59014:11: [preauth] Jul 25 21:36:40 hoge sshd[35767]: Disconnected from authenticating user root 180.101.88.251 port 59014 [preauth] Jul 25 21:36:40 hoge sshd[35767]: PAM 2 more authentication failures; logname= uid=0 euid=0 tty=ssh ruser= rhost=180.101.88.251 user=root Jul 25 21:36:58 hoge sshd[35774]: Accepted password for root from 60.88.119.57 port 51257 ssh2 Jul 25 21:36:58 hoge sshd[35774]: pam_unix(sshd:session): session opened for user root(uid=0) by root(uid=0) Jul 25 21:37:30 hoge sshd[35800]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=180.101.88.251 user=root Jul 25 21:37:32 hoge sshd[35800]: Failed password for root from 180.101.88.251 port 25418 ssh2 Jul 25 21:37:35 hoge sshd[35800]: Failed password for root from 180.101.88.251 port 25418 ssh2 Jul 25 21:37:38 hoge sshd[35800]: Failed password for root from 180.101.88.251 port 25418 ssh2 Jul 25 21:37:39 hoge sshd[35800]: Received disconnect from 180.101.88.251 port 25418:11: [preauth] Jul 25 21:37:39 hoge sshd[35800]: Disconnected from authenticating user root 180.101.88.251 port 25418 [preauth] Jul 25 21:37:39 hoge sshd[35800]: PAM 2 more authentication failures; logname= uid=0 euid=0 tty=ssh ruser= rhost=180.101.88.251 user=root

pofuda

2024/07/25 12:44

>>/etc/pam.d/dovecot の内容も関わってくるので、追記されたほうが良いかと思います。すみません、確かに追記したような覚えがありました。バックアップと照らし合わせたところ、追加したのは下二行の「auth」「account」になります。 /etc/pam.d/dovecot #%PAM-1.0 auth required pam_nologin.so auth include password-auth account include password-auth session include password-auth auth required pam_unix.so nullok account required pam_unix.so

pofuda

2024/07/25 12:47

>>cyrus-sasl-plain をインストールしてみてはいかがでしょうか？ yum install cyrus-sasl-plainを実行して確認したところ、cyrus-sasl-plainはインストール済みでした。 >>確認ですがユーザーhoge なら、USER hoge@domain.com ですよね？そうなのですね！すみません、ずっとアカウント名だけでログインしようとしていました・・・！次につまずく箇所だったので教えて下さりありがとうございます！

TaichiYanagiya

2024/07/25 13:00

PAM (auth-system.conf.ext) の場合はドメインなしでいいはず。 hoge ユーザーの OS パスワードを再設定してみましたか？

pofuda

2024/07/25 13:21

passwdコマンドで新しくパスワードを設定し直したところ、telnet localhost 110でログインができるようになりました！！ありがとうございます！以下がログになります！ Jul 25 22:11:12 hoge sshd[36181]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=59.50.17.5 user=nobody Jul 25 22:11:15 hoge sshd[36181]: Failed password for nobody from 59.50.17.5 port 41857 ssh2 Jul 25 22:11:16 hoge sshd[36181]: Connection closed by authenticating user nobody 59.50.17.5 port 41857 [preauth] Jul 25 22:11:17 hoge sshd[36184]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=220.248.205.14 user=nobody Jul 25 22:11:20 hoge sshd[36184]: Failed password for nobody from 220.248.205.14 port 1206 ssh2 Jul 25 22:11:21 hoge sshd[36184]: Connection closed by authenticating user nobody 220.248.205.14 port 1206 [preauth] Jul 25 22:11:38 hoge sshd[36186]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=180.101.88.251 user=root Jul 25 22:11:39 hoge sshd[36186]: Failed password for root from 180.101.88.251 port 20558 ssh2 Jul 25 22:11:43 hoge sshd[36186]: Failed password for root from 180.101.88.251 port 20558 ssh2 Jul 25 22:11:46 hoge sshd[36186]: Failed password for root from 180.101.88.251 port 20558 ssh2 Jul 25 22:11:47 hoge sshd[36186]: Received disconnect from 180.101.88.251 port 20558:11: [preauth] Jul 25 22:11:47 hoge sshd[36186]: Disconnected from authenticating user root 180.101.88.251 port 20558 [preauth] Jul 25 22:11:47 hoge sshd[36186]: PAM 2 more authentication failures; logname= uid=0 euid=0 tty=ssh ruser= rhost=180.101.88.251 user=root Jul 25 22:12:38 hoge sshd[36198]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=180.101.88.251 user=root Jul 25 22:12:40 hoge sshd[36198]: Failed password for root from 180.101.88.251 port 38475 ssh2 Jul 25 22:12:44 hoge sshd[36198]: Failed password for root from 180.101.88.251 port 38475 ssh2 Jul 25 22:12:46 hoge sshd[36198]: Failed password for root from 180.101.88.251 port 38475 ssh2 Jul 25 22:12:47 hoge sshd[36198]: Received disconnect from 180.101.88.251 port 38475:11: [preauth] Jul 25 22:12:47 hoge sshd[36198]: Disconnected from authenticating user root 180.101.88.251 port 38475 [preauth] Jul 25 22:12:47 hoge sshd[36198]: PAM 2 more authentication failures; logname= uid=0 euid=0 tty=ssh ruser= rhost=180.101.88.251 user=root Jul 25 22:12:48 hoge sshd[36201]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=60.88.119.57 user=root Jul 25 22:12:51 hoge sshd[36201]: Failed password for root from 60.88.119.57 port 53272 ssh2 Jul 25 22:12:58 hoge sshd[36201]: Accepted password for root from 60.88.119.57 port 53272 ssh2 Jul 25 22:12:58 hoge sshd[36201]: pam_unix(sshd:session): session opened for user root(uid=0) by root(uid=0)

pofuda

2024/07/25 13:53

無事にgmailでログインできるようになりました！パスワードを再設定すればいけるという初歩的なことで躓いてしまっていたとは…。ご回答を下さった方々、ありがとうございました！