| 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 >filename |
| 58 | 2>&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=<null>, sysgroupid=1001, homedir=/home/brian, address=brian, fullname=Brian Candler, maildir=<null>, quota=<null>, options=<null> |
| 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> |