CURL error when used to authenticate dovecot

[weirdnik]

Setup on a Debian Jessie, SSH and sudo work, but when used to authenticate IMAP access through dovecot, fails with "Error performing curl". This is just default Debian packaged deployment (pam-common) used for IMAP auth.

dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(830)] get user returned: REDACTED
dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(851)] get password returned: (null)
dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(972)] conv returned 53 bytes
dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(990)] Skipping first 9 bytes. Length is 53, token_id set to 12 and token OTP always 32.
dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(997)] OTP: [REDACTED] ID: [REDACTED]
dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1012)] Extracted a probable system password entered before the OTP - setting item PAM_AUTHTOK
dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1028)] ykclient return value (109): Error performing curl
dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1091)] done. [Authentication service cannot retrieve authentication info]

[klali]

What versions of libykclient and yubico-pam are you running?
Does the OTP printed in debug match the one you send to dovecot?
That error is returned in two places from libykclient, one of them (https://github.com/Yubico/yubico-c-client/blob/master/ykclient.c#L1240) writes to stderr with the preface "Error with curl:" can you see if that ends up in any of your logs?

[weirdnik]

# dpkg -l | grep yubi
ii  libpam-yubico                        2.17-2                     amd64        two-factor password and YubiKey OTP PAM module
ii  libyubikey0                          1.12-2                     amd64        Yubikey OTP handling library runtime
ii  python-yubico                        1.1.0-2                    all          Python code for talking to Yubico YubiKeys
ii  python-yubico-tools                  1.1.0-2                    all          Tools for Yubico YubiKeys

[weirdnik]

The quoted log is the only one that references curl, systemwide.

[weirdnik]

I have updated my system to stretch, and the error message now says there's double free:

dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(834)] get user returned: [REDACTED]
dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(855)] get password returned: (null)
dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(985)] conv returned 53 bytes
dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1003)] Skipping first 9 bytes. Length is 53, token_id set to 12 and token OTP always 32.
dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1010)] OTP: [REDACTED] ID: [REDACTED]
dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1025)] Extracted a probable system password entered before the OTP - setting item PAM_AUTHTOK
dovecot: auth-worker: Error: *** Error in `dovecot/auth': double free or corruption (!prev): 0x00007f389ba54e40 ***
dovecot: auth: Error: auth worker: Aborted PASSV request for [REDACTED]: Worker process died unexpectedly
dovecot: auth-worker: Fatal: master: service(auth-worker): child 1281 killed with signal 6 (core dumps disabled)```

[klali]

What pam-yubico version is this with? Would it be possible for you to try this with 2.24 or a git checkout?

[weirdnik]

This is Debian Stretch now, with libpam-yubico 2.23.

ii libpam-yubico 2.23-1 amd64 two-factor password and YubiKey OTP PAM module

Due to being a remote production machine I'd prefer to not risk breaking the auth system.

[klali]

There shouldn't be anything in 2.24 that makes a difference to this, so 2.23 should be recent enough to rule out any bugs already fixed.

There are issues when pam-yubico is pulled in by a program not linked with pthread with the name resolution in curl. Maybe you can check if the auth worker for dovecot links with pthread? If it doesn't that's a likely culprit (though the crash doesn't look specifically like that).

[weirdnik]

it seems that it is not, after enabling debugging the following appears in dovecot logs

Aug 27 18:31:50 vps dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1025)] Extracted a probable system password entered before the OTP - setting item PAM_AUTHTOK
Aug 27 18:31:51 vps dovecot: auth-worker: Error: *** Error in `dovecot/auth': double free or corruption (!prev): 0x00007fd69bcd7920 ***
Aug 27 18:31:51 vps dovecot: auth: Error: auth worker: Aborted PASSV request for alex: Worker process died unexpectedly
Aug 27 18:31:51 vps dovecot: auth-worker(6001): Fatal: master: service(auth-worker): child 6001 killed with signal 6 (core dumps disabled)

while auth is not linked with pthread:

root@vps:/usr/lib/dovecot# ldd auth
        linux-vdso.so.1 (0x00007ffc22079000)
        libstats_auth.so => /usr/lib/dovecot/modules/stats/libstats_auth.so (0x00007f98d3461000)
        libdovecot.so.0 => /usr/lib/dovecot/libdovecot.so.0 (0x00007f98d3139000)
        libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007f98d2f11000)
        libcrypt.so.1 => /lib/x86_64-linux-gnu/libcrypt.so.1 (0x00007f98d2cd1000)
        libpam.so.0 => /lib/x86_64-linux-gnu/libpam.so.0 (0x00007f98d2ac1000)
        libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f98d2719000)
        /lib64/ld-linux-x86-64.so.2 (0x00007f98d38c9000)
        libaudit.so.1 => /lib/x86_64-linux-gnu/libaudit.so.1 (0x00007f98d24e9000)
        libcap-ng.so.0 => /lib/x86_64-linux-gnu/libcap-ng.so.0 (0x00007f98d22d9000)

[klali]

Yes, this might be the same issue: #31
I'd say that the recommended workaround for this is to use nscd for name resolution. You can also reduce the list of servers to a single one, but that has problems with single point of failure.

[weirdnik]

I reset the server list to one:

auth    required        pam_yubico.so mode=client try_first_pass id=[redacted] debug key=[redacted] urllist=https://api.yubico.com/wsapi/2.0/verify

and it still fails:

Aug 28 22:51:16 vps dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(819)] pam_yubico version: 2.23
Aug 28 22:51:16 vps dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(834)] get user returned: [redacted]
Aug 28 22:51:16 vps dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(855)] get password returned: (null)
Aug 28 22:51:16 vps dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(985)] conv returned 53 bytes
Aug 28 22:51:16 vps dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1003)] Skipping first 9 bytes. Length is 53, token_id set to 12 and token OTP always 32.
Aug 28 22:51:16 vps dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1010)] OTP: [redacted] ID: [redacted]
Aug 28 22:51:16 vps dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1025)] Extracted a probable system password entered before the OTP - setting item PAM_AUTHTOK
Aug 28 22:51:17 vps dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1040)] ykclient return value (0): Success
Aug 28 22:51:17 vps dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1041)] ykclient url used: https://api.yubico.com/wsapi/2.0/verify?[redacted]
Aug 28 22:51:17 vps dovecot: auth-worker: Error: [../pam_yubico.c:authorize_user_token(168)] getpwnam_r: Success
Aug 28 22:51:17 vps dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1070)] Internal error while validating user
Aug 28 22:51:17 vps dovecot: auth-worker: Error: [../pam_yubico.c:pam_sm_authenticate(1109)] done. [Authentication service cannot retrieve authentication info]

[klali]

Though it seems to be failing in a different way. The debug messages are quite bad (I'll improve them..) but the presence of "getpwnam_r: Success" indicates that the user is not found in that call. Before this you saw actual crashes from the process.