README.authdebug.html.in

   1 <!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
   2     "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
   3
   4 <html xmlns="http://www.w3.org/1999/xhtml">
   5 <head>
   6   <meta http-equiv="Content-Type" content="" />
   7
   8   <title>Debugging authentication problems</title>
   9 </head>
  10
  11 <body bgcolor="#FFFFFF">
  12   <h1 align="center">Debugging authentication problems</h1>
  13
  14   <p>A common problem after installing the Courier authentication
  15   library is that authentication, using authtest, doesn't work.
  16   This document shows how to use courier's debugging features to
  17   pinpoint the problem.</p>
  18
  19   <h2>1. Turn on debugging</h2>
  20
  21   <p>For courier-imap, you need to set one of the following values
  22   in @sysconfdir@/authdaemonrc:</p>
  23   <pre>
  24 DEBUG_LOGIN=1    # turn on authentication debugging
  25 DEBUG_LOGIN=2    # turn on authentication debugging AND show passwords
  26 </pre>
  27
  28   <p>This setting is located at the very end of the configuration
  29   file.</p>
  30
  31   <p>After changing this setting, restart the authentication daemon
  32   by running the "authdaemond stop" and "authdaemond start"
  33   commands.</p>
  34
  35   <p>At this point, all debugging output goes to syslog at level
  36   'debug', which is normally not shown. You will probably need to
  37   change your <code>/etc/syslog.conf</code> file to be able to see
  38   these messages. If you have an existing entry which says
  39   "mail.info" (which means facility 'mail', level 'info' or higher)
  40   then you can just change this to "mail.debug". Alternatively you
  41   can add a new entry like this:</p>
  42   <pre>
  43 *.debug                        /var/log/debug
  44 </pre>
  45
  46   <p>Don't forget to create this file, and to send a HUP signal to
  47   syslogd to make it re-read its configuration:</p>
  48   <pre>
  49 # touch /var/log/debug
  50 # killall -1 syslogd
  51 </pre>
  52
  53   <p>If you don't want to mess around with your syslog
  54   configuration, you can also start <code>authdaemond</code>
  55   manually, and log its output to a file:</p>
  56
  57   <p><code>@libexecdir@/courier-authlib/authdaemond &gt;filename
  58   2&gt;&amp;1</code></p>
  59
  60   <h2>2. Issue a manual login</h2>
  61
  62   <p>You can use the authtest command to verify authentication, or
  63   go ahead and install Courier-IMAP.</p>
  64
  65   <p>For courier-imap, you will get much better information by not
  66   using a mail client and manually logging in using 'telnet'. The
  67   transcript of this telnet session may give useful information as
  68   to what is going on. If you are going to report a problem to the
  69   mailing list, you should certainly include this transcript as
  70   well as the corresponding debugging output.</p>
  71   <pre>
  72 -- to debug POP3 --
  73 # telnet x.x.x.x 110
  74 user USERNAME
  75 pass PASSWORD
  76 stat
  77 quit
  78
  79 -- to debug IMAP --
  80 # telnet x.x.x.x 143
  81 a login USERNAME PASSWORD
  82 a examine inbox
  83 a logout
  84
  85 -- to debug POP3 over SSL --
  86 # openssl s_client -connect x.x.x.x:995
  87 (then use same commands as POP3 example)
  88
  89 -- to debug IMAP over SSL --
  90 # openssl s_client -connect x.x.x.x:993
  91 (then use same commands as IMAP example)
  92 </pre>
  93
  94   <p>This isn't an option for sqwebmail of course - just login
  95   through the web interface and check the authentication debug log
  96   which is generated.</p>
  97
  98   <h2>3. Interpret the debug output</h2>
  99
 100   <p>First, a brief explanation of courier's authentication system.
 101   There are a number of standalone <b>authentication modules</b>.
 102   An authentication module exists for every authentication method.
 103   Each authentication module is installed as a shared library. When
 104   <strong>authdaemond</strong> starts, it attempts to load and
 105   initialize the authentication modules, logging the following
 106   messages to syslog:</p>
 107   <pre>
 108 Oct 17 11:25:37 commodore authdaemond: modules="authuserdb authpam authpgsql authldap authmysql authcustom", daemons=5
 109 Oct 17 11:25:37 commodore authdaemond: Installing libauthuserdb
 110 Oct 17 11:25:37 commodore authdaemond: Installation complete: authuserdb
 111 Oct 17 11:25:37 commodore authdaemond: Installing libauthpam
 112 Oct 17 11:25:37 commodore authdaemond: Installation complete: authpam
 113 Oct 17 11:25:37 commodore authdaemond: Installing libauthpgsql
 114 Oct 17 11:25:37 commodore authdaemond: libauthpgsql.so: cannot open shared object file: No such file or directory
 115 Oct 17 11:25:37 commodore authdaemond: Installing libauthldap
 116 Oct 17 11:25:37 commodore authdaemond: libauthldap.so: cannot open shared object file: No such file or directory
 117 Oct 17 11:25:37 commodore authdaemond: Installing libauthmysql
 118 Oct 17 11:25:37 commodore authdaemond: libauthmysql.so: cannot open shared object file: No such file or directory
 119 Oct 17 11:25:37 commodore authdaemond: Installing libauthcustom
 120 Oct 17 11:25:37 commodore authdaemond: Installation complete: authcustom
 121 </pre>
 122
 123   <p>The first message lists all authentication modules that were
 124   compiled, and indicates that <strong>authdaemond</strong> will
 125   spawn five processes to handle all authentication requests. This
 126   is followed by messages indicating that indicate which
 127   authentication modules were installed.</p>
 128
 129   <p>In this example, authdaemond did not load the authpgsql,
 130   authldap, and authmysql modules. That's because in this case the
 131   Courier authentication library is installed by the system's
 132   package manager. The LDAP, MySQL, and PostgreSQL support was
 133   placed into optional sub-packages which are not installed. Even
 134   though all of these modules were initially compiled, the optional
 135   authentication modules were not installed.</p>
 136
 137   <p>This is normal. authdaemond will simply ignore any
 138   authentication module it cannot find, and will activate only
 139   those modules that are available. When an authentication request
 140   comes in, all of the modules will be executed, one after the
 141   other, resulting in one of three conditions:</p>
 142
 143   <dl>
 144     <dt>ACCEPT</dt>
 145
 146     <dd>The user was authenticated successfully</dd>
 147
 148     <dt>REJECT</dt>
 149
 150     <dd>The module did not know this username, or the user gave
 151     invalid credentials. The request is passed to the next
 152     module.</dd>
 153
 154     <dt>TEMPFAIL</dt>
 155
 156     <dd>The module suffered an internal failure, such as inability
 157     to contact an external database. The login is rejected, and no
 158     further modules are tried.</dd>
 159   </dl>
 160
 161   <p>In a typical Courier installation the authentication request
 162   is sent, via a filesystem socket, to a pool of <b>authdaemond</b>
 163   processes (note the extra "d" on the end) which perform the
 164   actual work. authdaemond, in turn, contains other authentication
 165   modules such as authpam, authmysql, and so on.</p>
 166
 167   <p>If <code>authdaemond</code> is running successfully, then it
 168   will in turn run each of the modules it is linked against. If any
 169   one returns REJECT then the next is tried; if any returns
 170   TEMPFAIL or ACCEPT then no further modules are tried.</p>
 171
 172   <p>So a typical example might look like this:</p>
 173   <pre>
 174 Apr 14 14:07:15 billdog authdaemond: received auth request, service=pop3, authtype=login
 175 Apr 14 14:07:15 billdog authdaemond: authcustom: trying this module
 176 Apr 14 14:07:15 billdog authdaemond: authcustom: nothing implemented in do_auth_custom()
 177 Apr 14 14:07:15 billdog authdaemond: authcustom: REJECT - try next module
 178 Apr 14 14:07:15 billdog authdaemond: authcram: trying this module
 179 Apr 14 14:07:15 billdog authdaemond: cram: only supports authtype=cram-*
 180 Apr 14 14:07:15 billdog authdaemond: authcram: REJECT - try next module
 181 Apr 14 14:07:15 billdog authdaemond: authuserdb: trying this module
 182 Apr 14 14:07:15 billdog authdaemond: userdb: opened /etc/userdb.dat
 183 Apr 14 14:07:15 billdog authdaemond: userdb: looking up 'brian'
 184 Apr 14 14:07:15 billdog authdaemond: userdb: entry not found
 185 Apr 14 14:07:15 billdog authdaemond: authuserdb: REJECT - try next module
 186 Apr 14 14:07:15 billdog authdaemond: authpam: trying this module
 187 Apr 14 14:07:15 billdog authdaemond: authpam: sysusername=brian, sysuserid=&lt;null&gt;, sysgroupid=1001, homedir=/home/brian, address=brian, fullname=Brian Candler, maildir=&lt;null&gt;, quota=&lt;null&gt;, options=&lt;null&gt;
 188 Apr 14 14:07:15 billdog authdaemond: pam_service=pop3, pam_username=brian
 189 Apr 14 14:07:15 billdog authdaemond: dopam successful
 190 Apr 14 14:07:15 billdog authdaemond: authpam: ACCEPT, username brian
 191 </pre>
 192
 193   <p>What's happening here?</p>
 194
 195   <ul>
 196     <li>The request was received by 'authdaemond'</li>
 197
 198     <li>It tries 'authcustom' - this module does nothing unless you
 199     have customised it yourself, so it REJECTs the request</li>
 200
 201     <li>It tried 'authcram', but since this was a request with
 202     authtype=login (rather than authtype=cram-md5, say), this
 203     module cannot handle it so it REJECTs</li>
 204
 205     <li>'authuserdb' has a go. In this case there is an
 206     /etc/userdb.dat file for it to look in, but the requested
 207     username 'brian' does not exist in there, so it REJECTs</li>
 208
 209     <li>'authpam' has a go. It finds the username and home
 210     directory in /etc/passwd, and then calls the PAM subsystem to
 211     authenticate. The authentication is successful.</li>
 212   </ul>
 213
 214   <p>So, in principle, debugging is straightforward. Watch the
 215   modules operate, search for the one which you <i>think</i> should
 216   be authenticating the user, and if it is not, check for REJECT
 217   (user not known or password mismatch) or TEMPFAIL (internal
 218   error) status. Additional messages should indicate why this
 219   status was returned.</p>
 220
 221   <h2>4. Read the documentation</h2>
 222
 223   <p>Most of the configuration files like authldaprc, authmysql are
 224   well documented with comments.</p>
 225
 226   <p>For the nitty-gritty details of authentication modules, see
 227   <a href="http://www.courier-mta.org/authlib.html">man
 228   authlib</a>. There is probably a copy of this manpage installed
 229   on your system; if that command doesn't work, try one of
 230   these:</p>
 231   <pre>
 232 # man -M @prefix@/man authlib
 233 or
 234 # cd /path/to/sources
 235 # cd authlib
 236 # nroff -mandoc authlib.7.in | less
 237 </pre>
 238
 239   <p>If you are using userdb authentication, you definitely need to
 240   read <a href="http://www.courier-mta.org/makeuserdb.html">man
 241   makeuserdb</a>, <a href=
 242   "http://www.courier-mta.org/userdb.html">man userdb</a>, and
 243   <a href="http://www.courier-mta.org/userdbpw.html">man
 244   userdbpw</a>.</p>
 245
 246   <h2>5. Use the mailing list</h2>
 247
 248   <p>Please read through the common problems and solutions at the
 249   bottom of this document. The next thing to do, of course, is
 250   search the web to see if your particular problem has been seen
 251   before and solved. <a href="http://www.google.com">Google</a> is
 252   very good for this.</p>
 253
 254   <p>If you still cannot work out what the problem is, then you can
 255   ask on the appropriate <a href=
 256   "http://www.courier-mta.org/links.html">mailing list</a>. But
 257   before you post, please gather together all the following
 258   information:</p>
 259
 260   <ul>
 261     <li>The operating system and version you are running</li>
 262
 263     <li>The versions of packages you have installed</li>
 264
 265     <li>The <code>./configure</code> command line you gave to build
 266     it</li>
 267
 268     <li>If you didn't build it yourself, where you got the package
 269     from (and if possible, find out from the packager what options
 270     they used to build it)</li>
 271
 272     <li>The versions of any other relevant software which you are
 273     linking against, e.g. openldap, mysql, pgsql</li>
 274
 275     <li>The transcript of the 'telnet' session you used to manually
 276     test server connections</li>
 277
 278     <li>The corresponding debug output which was generated for that
 279     session</li>
 280
 281     <li>The contents of relevant configuration files, e.g.
 282     authldaprc, authmysqlrc, imapd, pop3d</li>
 283
 284     <li>A copy of the database entry you are trying to authenticate
 285     against: e.g. the line from your userdb file, an LDAP entry, a
 286     row from your mysql table, the line in /etc/password, etc.</li>
 287   </ul>
 288
 289   <p>If you include all this, you are <i>much</i> more likely to
 290   get a helpful response.</p>
 291   <hr />
 292
 293   <h2>Frequently seen authentication problems and solutions</h2>
 294
 295   <p>See also the <a href=
 296   "http://www.courier-mta.org/FAQ.html">Courier MTA FAQ</a></p>
 297
 298   <h3>When I try to login with POP3 using telnet, the server
 299   disconnects immediately after the "PASS" command, without giving
 300   a -ERR response</h3>
 301
 302   <p>The reason for this error will probably be found in your mail
 303   logs. Usually it indicates either that the home directory does
 304   not exist (chdir failed), or the Maildir has not been created.
 305   See 'man maildirmake'.</p>
 306
 307   <h3>PAM authentication says "pam_start failed, result 4 [Hint:
 308   bad PAM configuration?]"</h3>
 309
 310   <p>Probably your PAM configuration is bad. If you have
 311   /etc/pam.d/other, then try simply removing /etc/pam.d/pop3 and
 312   /etc/pam.d/imap and see if it works (this is sufficient for
 313   FreeBSD). Otherwise, try copying one of your existing
 314   /etc/pam.d/xxx files to /etc/pam.d/pop3, imap or webmail
 315   respectively.<br />
 316   The result value is a PAM_XXXX constant from
 317   <code>/usr/include/security/pam_constants.h</code> (this file may
 318   be in a different location on your system). Under FreeBSD, 4 is
 319   PAM_SYSTEM_ERR.</p>
 320
 321   <h3>When I connect on the SSL ports (995 or 993), the server
 322   accepts the connection but then immediately disconnects</h3>
 323
 324   <p>You probably didn't install any SSL certificates. Courier-imap
 325   comes with scripts you can run to do this for you:</p>
 326   <pre>
 327 # @prefix@/sbin/mkimapdcert
 328 # @prefix@/sbin/mkpop3dcert
 329 </pre>
 330
 331   <h3>I expected the authentication library to compile authmysql
 332   (or some other module), but it's not there</h3>
 333
 334   <p>If the mysql authentication module did not compile, then
 335   perhaps ./configure was unable to find your mysql libraries (you
 336   can read through the file 'config.log' in the source directory to
 337   see what it found). You may need to force it to look in the right
 338   place, as follows:</p>
 339   <pre>
 340 # ./configure --with-authmsql --with-mysql-libs=/usr/local/mysql/lib  \
 341               --with-mysql-includes=/usr/local/mysql/include
 342 </pre>
 343
 344   <p>On some systems (e.g. FreeBSD), the mysqlclient library
 345   depends on the math and compression libraries. For these systems,
 346   try:</p>
 347   <pre>
 348 # LDFLAGS="-lm -lz" ./configure --with-authmysql ... same as before
 349 </pre>
 350
 351   <h3>The POP3/IMAP server says "Temporary problem, please try
 352   again later" when a bad password is entered</h3>
 353
 354   <p><code>authdaemond</code> tries each of the configured
 355   authentication modules in turn, until either one accepts the
 356   login, or they have all rejected it (in which case the usual
 357   "Login failed" error is returned, and the user can try
 358   again).</p>
 359
 360   <p>However, if one of these modules is unable to run because some
 361   resource is not available, then it gives a "temporary failure"
 362   response and no further modules are tried. You should find the
 363   exact cause in your mail logs, but typically it means that you
 364   have a module like 'authmysql' in your module list, but the mysql
 365   database is not running.</p>
 366
 367   <p>So unless you actually do have account data in mysql (in which
 368   case you need to fix your mysql setup), you should remove
 369   'authmysql' and any other modules you do not use from
 370   <code>authmodulelist</code> in <code>authdaemonrc</code>.</p>
 371 </body>
 372 </html>