From owner-freebsd-questions@freebsd.org Sat Feb 2 21:40:46 2019 Return-Path: Delivered-To: freebsd-questions@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 9DBF614D0C46 for ; Sat, 2 Feb 2019 21:40:46 +0000 (UTC) (envelope-from plmahan@gmail.com) Received: from mail-vs1-xe36.google.com (mail-vs1-xe36.google.com [IPv6:2607:f8b0:4864:20::e36]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G3" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 474476AFC9 for ; Sat, 2 Feb 2019 21:40:45 +0000 (UTC) (envelope-from plmahan@gmail.com) Received: by mail-vs1-xe36.google.com with SMTP id u11so6373882vsp.11 for ; Sat, 02 Feb 2019 13:40:45 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:from:date:message-id:subject:to; bh=ujHSui8Gc0kB6+nzY3SpGEfevfH2tGArKPFyvwc8g9I=; b=bCNm+NwuQ1syyvv/kDGAKlqDDjcb1SS3wHWLNYAVXkkRX5NOHoMpb1+jBWF1wFm/zg uRTvG48JBsPqn41vOQA2c4IJgkhziDZv+p8y1jGNzq0XE2JwhZcdJo4kCuRx4fLFwv4m NqcRH9V73G8OnSFrrZ2lauUUKDYSkA2BAyrRmZfPBVbp7x9BYLTRnQuMrrU3Df2QCOcN 940m+gcWJ7Q3ARfR9rnvu8S73Fvi9LG9EMvXVPzQSXPvdVD2i1tEeURCmLi/Gel0hbeC SrcltxjZqXnAd3pjzPb4kN5g/PuyRrjC+e00ZNUdFhn7lYearMxm91C+cRBhLreNESns b8MA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:from:date:message-id:subject:to; bh=ujHSui8Gc0kB6+nzY3SpGEfevfH2tGArKPFyvwc8g9I=; b=BmJBGztCuLwamzvCVSuviv9qyF6Y7RrYN3SDc6RZYbqk9TG0vBhD5jgdlUy3EIZ4HO syZLX7vG9mGj2RtXJuiBnmLJfuVSobKKp/q9avKFtvLzzTuzm+JJTdW1sMrXkBk0P49Q olci2PA1KXwA3uk/fp9i8LhRpOexyVHsK4kMYw0dP2W0EBoHxO32ZntOmywD0z6Co4Cf TyNY+fo2GyMtQuYzYYkjhN3xjt8KbfIe601fmYFtdAim8no8f8NDs7ujv0m7RyexVIv5 GSQ0JbRDXHXaX8w1fqa1hTC71dPmDSEJ/sdmIzBOIBKYpUa7ra0Mhz+TuvQbibcbraYt Ni/w== X-Gm-Message-State: AJcUukeSUa1/g9YN4fDmwYz2rGwA5yziYXMeltUY9mAH39mlwlSXz2xY Zwv+jZ2cuvi7IhqD/NEApAH+KuEvfJAAjXFngUJyQqT0 X-Google-Smtp-Source: ALg8bN5qzcRbJa6q01LYG3AbmMRlKBc74qJn5IGIzUkWx1Vl3TK5VohrTAH6Qx3tO5ma9ZofSTWsIKjxbboBMSEuiA8= X-Received: by 2002:a67:c86:: with SMTP id 128mr20529759vsm.221.1549143643866; Sat, 02 Feb 2019 13:40:43 -0800 (PST) MIME-Version: 1.0 From: Patrick Mahan Date: Sat, 2 Feb 2019 13:40:32 -0800 Message-ID: Subject: Help debugging pam authentication for dovecot To: User Questions X-Rspamd-Queue-Id: 474476AFC9 X-Spamd-Bar: ------ Authentication-Results: mx1.freebsd.org; dkim=pass header.d=gmail.com header.s=20161025 header.b=bCNm+Nwu; dmarc=pass (policy=none) header.from=gmail.com; spf=pass (mx1.freebsd.org: domain of plmahan@gmail.com designates 2607:f8b0:4864:20::e36 as permitted sender) smtp.mailfrom=plmahan@gmail.com X-Spamd-Result: default: False [-6.42 / 15.00]; ARC_NA(0.00)[]; NEURAL_HAM_MEDIUM(-1.00)[-1.000,0]; R_DKIM_ALLOW(-0.20)[gmail.com:s=20161025]; FROM_HAS_DN(0.00)[]; R_SPF_ALLOW(-0.20)[+ip6:2607:f8b0:4000::/36]; FREEMAIL_FROM(0.00)[gmail.com]; MIME_GOOD(-0.10)[multipart/alternative,text/plain]; PREVIOUSLY_DELIVERED(0.00)[freebsd-questions@freebsd.org]; NEURAL_HAM_LONG(-1.00)[-1.000,0]; RCPT_COUNT_ONE(0.00)[1]; RCVD_TLS_LAST(0.00)[]; TO_DN_ALL(0.00)[]; DKIM_TRACE(0.00)[gmail.com:+]; DMARC_POLICY_ALLOW(-0.50)[gmail.com,none]; RCVD_IN_DNSWL_NONE(0.00)[6.3.e.0.0.0.0.0.0.0.0.0.0.0.0.0.0.2.0.0.4.6.8.4.0.b.8.f.7.0.6.2.list.dnswl.org : 127.0.5.0]; MX_GOOD(-0.01)[cached: alt3.gmail-smtp-in.l.google.com]; TO_MATCH_ENVRCPT_ALL(0.00)[]; IP_SCORE(-2.85)[ip: (-9.83), ipnet: 2607:f8b0::/32(-2.40), asn: 15169(-1.92), country: US(-0.07)]; NEURAL_HAM_SHORT(-0.56)[-0.561,0]; FROM_EQ_ENVFROM(0.00)[]; MIME_TRACE(0.00)[0:+,1:+]; FREEMAIL_ENVFROM(0.00)[gmail.com]; ASN(0.00)[asn:15169, ipnet:2607:f8b0::/32, country:US]; RCVD_COUNT_TWO(0.00)[2]; DWL_DNSWL_NONE(0.00)[gmail.com.dwl.dnswl.org : 127.0.5.0] Content-Type: text/plain; charset="UTF-8" X-Content-Filtered-By: Mailman/MimeDel 2.1.29 X-BeenThere: freebsd-questions@freebsd.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: User questions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 02 Feb 2019 21:40:46 -0000 FreeBSD 11.2-RELEASE-p7 Dovecot 2.3.4 Postfix 3.3.2 I recently upgraded my domain server (mahan.org) from FBSD 9.2 to FBSD 11.2. Due to some configuration issues with my sendmail due to the upgrade, I was suddenly relaying spam. I decided it was time to switch to something newer and after a little research installed postfix. I then modified the dovecot config to support postfix instead of sendmail. This has shutdown the spam relaying. However a new issue has cropped up. I cannot access mail via IMAP through dovecot. The failure seems to be with the user authentication, which is configured to use PAM. My imap client (both thunderbird and iOS mail) report that the password is invalid. Looking at both maillog, auth.log and debug.log I see that PAM is refusing authentication. My /usr/local/pam.d/dovecot file contains - # # ns.mahan.org - dovecot pam config # Use pam to access standard user passwd # # PAM configuration for the "dovecot" service # # auth auth required pam_unix.so debug nullok local_pass # account account required pam_unix.so debug try_first_pass local_pass I have testing using the pamtester-0.1.2 and the user authentication passes. I cannot understand what the failure mode code be with dovecot. The command I used was 'pamtester -v dovecot mahan authenticate' As you can see I have enabled PAM debugging and have that output, but it is rather involved so I was going to wait until it was requested. Based on the debug output I see some differences (1 minor, 1 major): Both ways cause the following log message - Feb 2 12:43:24 ns pamtester: in pam_sm_authenticate(): Got user: mahan Feb 2 12:43:24 ns pamtester: in pam_sm_authenticate(): Doing real authentication The minor difference I see is - with pamtester Feb 2 12:43:24 ns pamtester: in pam_get_authtok(): entering Feb 2 12:43:24 ns pamtester: in pam_get_item(): entering: PAM_RHOST Feb 2 12:43:24 ns pamtester: in pam_get_item(): returning PAM_SUCCESS Feb 2 12:43:24 ns pamtester: in pam_get_item(): entering: PAM_OLDAUTHTOK Feb 2 12:43:24 ns pamtester: in pam_get_item(): returning PAM_SUCCESS with dovecot Feb 2 12:46:19 ns auth: in pam_get_authtok(): entering Feb 2 12:46:19 ns auth: in pam_get_item(): entering: PAM_RHOST Feb 2 12:46:19 ns auth: in pam_get_item(): returning PAM_SUCCESS Feb 2 12:46:19 ns auth: in pam_get_item(): entering: PAM_HOST Feb 2 12:46:19 ns auth: in pam_get_item(): returning PAM_SUCCESS Feb 2 12:46:19 ns auth: in pam_get_item(): entering: PAM_OLDAUTHTOK Feb 2 12:46:19 ns auth: in pam_get_item(): returning PAM_SUCCESS Dovecot causes PAM_HOST get item. This may be something that can be included with the '-I' option of pamtester, so I do think it is really an issue. The major difference I see is - with pamtester Feb 2 12:43:24 ns pamtester: in openpam_get_option(): entering: 'authtok_prompt' Feb 2 12:43:24 ns pamtester: in openpam_get_option(): returning NULL Feb 2 12:43:24 ns pamtester: in pam_get_item(): entering: PAM_AUTHTOK_PROMPT Feb 2 12:43:24 ns pamtester: in pam_get_item(): returning PAM_SUCCESS Feb 2 12:43:24 ns pamtester: in openpam_subst(): entering: 'Password:' Feb 2 12:43:24 ns pamtester: in openpam_subst(): returning PAM_SUCCESS with dovecot Feb 2 12:46:19 ns auth: in openpam_get_option(): entering: 'authtok_prompt' Feb 2 12:46:19 ns auth: in openpam_get_option(): returning NULL Feb 2 12:46:19 ns auth: in pam_get_item(): entering: PAM_AUTHTOK_PROMPT Feb 2 12:46:19 ns auth: in pam_get_item(): returning PAM_SUCCESS Feb 2 12:46:19 ns auth: in openpam_subst(): entering: 'Password for %u@%h:' Feb 2 12:46:19 ns auth: in pam_get_item(): entering: PAM_USER Feb 2 12:46:19 ns auth: in pam_get_item(): returning PAM_SUCCESS Feb 2 12:46:19 ns auth: in pam_get_item(): entering: PAM_HOST Feb 2 12:46:19 ns auth: in pam_get_item(): returning PAM_SUCCESS Feb 2 12:46:19 ns auth: in openpam_subst(): returning PAM_SUCCESS I don't know if this is the problem. I am unsure how this works differently between pamtester and dovecot so I am looking for some help here. After these lines, I see for pamtester - Feb 2 12:43:27 ns pamtester: in pam_sm_authenticate(): Got password Feb 2 12:43:27 ns pamtester: in openpam_dispatch(): /usr/lib/pam_unix.so.6: pam_sm_authenticate(): success while with dovecot Feb 2 12:46:19 ns auth: in pam_vprompt(): returning PAM_SUCCESS Feb 2 12:46:19 ns auth: in openpam_dispatch(): /usr/lib/pam_unix.so.6: pam_sm_authenticate(): authentication error I'm sure I have something odd configured in dovecot, but after working through a couple of examples on the web, I don't see what I have done incorrectly. Corrections, pointers, help is welcomed. Thanks Patrick