ccid_usb: Use CLOCK_MONOTONIC for timeouts

[hendrikdonner]

The pthread API unfortunately expects an absolute timestamp and not a duration value. With CLOCK_REALTIME changes to the system clock can result in timeouts happening earlier than expected, so use CLOCK_MONOTONIC instead.

[hendrikdonner]

I'm not sure if pthread_condattr_setclock is available on all target platforms, i can't really test e.g. MacOS.
So maybe need to add something like this:

--- a/configure.ac
+++ b/configure.ac
@@ -74,7 +74,7 @@ AC_C_CONST
 AC_TYPE_SIZE_T

 # Checks for library functions.
-AC_CHECK_FUNCS(select strerror strncpy memcpy strlcpy strlcat)
+AC_CHECK_FUNCS(select strerror strncpy memcpy strlcpy strlcat pthread_condattr_setclock)

 # Select OS specific versions of source files.
 AC_SUBST(BUNDLE_HOST)
diff --git a/src/ccid_usb.c b/src/ccid_usb.c
index 9a3389a..a85827f 100644
--- a/src/ccid_usb.c
+++ b/src/ccid_usb.c
@@ -42,6 +42,9 @@
 #include "ccid_ifdhandler.h"
 #include "sys_generic.h"

+#ifndef HAVE_PTHREAD_CONDATTR_SETCLOCK
+#define pthread_condattr_setclock(a, b) do {} while(0)
+#endif

 /* write timeout
  * we don't have to wait a long time since the card was doing nothing */

[LudovicRousseau]

Just curious:

• What reader do you use?
• How did you noticed the problem?

[hendrikdonner]

Just curious:

* What reader do you use?

* How did you noticed the problem?

It's happening on an embedded system we develop a custom Linux distro for, the issues was initially noticed when the card was in use while something else changed the clock. Very hard to reproduce, it depends on the timing, usually the system clock does not change that much. But it happened a few times during integration tests and only since 1.5.0.

Syslog had this:

pcscd: ccid_usb.c:1035:ReadUSB() read failed (2/3): 110 Connection timed out
pcscd: ifdwrapper.c:364:IFDStatusICC() Card not transacted: 612
pcscd: winscard.c:333:SCardConnect() Error powering up card: rv=SCARD_E_NOT_TRANSACTED

Got it down to the following one line reproducer:

date -s 13:43:42; pkcs11-tool --read --type cert -o /tmp/crt.der & sleep 0.2; date -s 14:43:42

Very much always errors out without the patch, can't trigger it with the patch anymore.

[LudovicRousseau]

Interesting.
The timeout should be 3 seconds. So I am surprised it occured, even if the clock go back of 1 second.

Can you reproduce the problem and generate a full pcscd log as documented at https://ccid.apdu.fr/#support ?

[hendrikdonner]

Interesting. The timeout should be 3 seconds. So I am surprised it occured, even if the clock go back of 1 second.

The problem is the clock jumping forwards, which cuts the actual timeout short. Notice how my one liner jumps 1h ahead. This is really just a "CLOCK_REALTIMEis allowed to change" issue.

Can you reproduce the problem and generate a full pcscd log as documented at https://ccid.apdu.fr/#support ?

I can look into it when i find the time.

I want to add this isn't an unknown issue all in all, libusb initializes its pthread_cond_t this way for a reason:

void usbi_cond_init(pthread_cond_t *cond)
{
#ifdef HAVE_PTHREAD_CONDATTR_SETCLOCK
    pthread_condattr_t condattr;

    PTHREAD_CHECK(pthread_condattr_init(&condattr));
    PTHREAD_CHECK(pthread_condattr_setclock(&condattr, CLOCK_MONOTONIC));
    PTHREAD_CHECK(pthread_cond_init(cond, &condattr));
    PTHREAD_CHECK(pthread_condattr_destroy(&condattr));
#else
    PTHREAD_CHECK(pthread_cond_init(cond, NULL));
#endif
}

int usbi_cond_timedwait(pthread_cond_t *cond,
    pthread_mutex_t *mutex, const struct timeval *tv)
{
    struct timespec timeout;
    int r;

#ifdef HAVE_PTHREAD_CONDATTR_SETCLOCK
    usbi_get_monotonic_time(&timeout);
#else
    usbi_get_real_time(&timeout);
#endif

    timeout.tv_sec += tv->tv_sec;
    timeout.tv_nsec += tv->tv_usec * 1000L;
    if (timeout.tv_nsec >= NSEC_PER_SEC) {
        timeout.tv_nsec -= NSEC_PER_SEC;
        timeout.tv_sec++;
    }

    r = pthread_cond_timedwait(cond, mutex, &timeout);
    if (r == 0)
        return 0;
    else if (r == ETIMEDOUT)
        return LIBUSB_ERROR_TIMEOUT;
    else
        return LIBUSB_ERROR_OTHER;
}

See libusb/libusb@ccba488 for the rational.

[LudovicRousseau]

I am not able to reproduce the problem on a Debian GNU/Linux system.
pthread_cond_timedwait() does not return with timeout if I change the system time 1 hour before.

What multi-slot reader do you use?

[hendrikdonner]

I am not able to reproduce the problem on a Debian GNU/Linux system. pthread_cond_timedwait() does not return with timeout if I change the system time 1 hour before.

Of course it doesn't work if you go into the past, I already explained you have to jump forward. The pthread_cond_timedwait() call takes an absolute time you set in the future, you want to jump close to or even ahead of that time.

And it very much comes back with a timeout. Considers this simple example:

#include <pthread.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <time.h>
#include <unistd.h>
#include <stdbool.h>

pthread_mutex_t m = PTHREAD_MUTEX_INITIALIZER;
pthread_cond_t c;

int main(int argc, char* argv[])
{
    struct timespec to;
    int retval;
    pthread_condattr_t attr;
    bool monotonic = false;

    fprintf(stderr, "starting...\n");

    if (argc > 1)
        if (0 == strcmp("monotonic", argv[1])) {
            monotonic = true;
            fprintf(stderr, "using CLOCK_MONOTONIC\n");
        }

    /* Set up the condvar attributes to use CLOCK_MONOTONIC. */

    pthread_condattr_init( &attr);
    pthread_condattr_setclock( &attr, monotonic ? CLOCK_MONOTONIC : CLOCK_REALTIME);
    pthread_cond_init( &c, &attr);

    /*
     Here's the interesting bit; we'll wait for
     five minutes FROM NOW when we call
     pthread_cond_timedwait().
    */
    clock_gettime(monotonic ? CLOCK_MONOTONIC : CLOCK_REALTIME, &to);
    to.tv_sec += 5 * 60;

    if ((retval = pthread_mutex_lock(&m))) {
        fprintf(stderr, "pthread_mutex_lock %s\n",
                strerror(retval));

        exit(EXIT_FAILURE);
    }

    if ((retval = pthread_cond_timedwait(&c, &m, &to)))
    {
        fprintf(stderr, "pthread_cond_timedwait %s\n",
                strerror(retval));

        exit(EXIT_FAILURE);
    }

    if ((retval = pthread_mutex_unlock(&m))) {
        fprintf(stderr, "pthread_mutex_unlock %s\n",
                strerror(retval));

        exit(EXIT_FAILURE);
    }

    return EXIT_SUCCESS;
}

It's a very simple example that waits in pthread_cond_timedwait for 5 minutes.

Compile gcc -o pthread_cond_timedwait example.c and run like this:

./pthread_cond_timedwait monotonic & sleep 2s; date -s "$(date -d '5 minutes')"

and ./pthread_cond_timedwait & sleep 2s; date -s "$(date -d '5 minutes')".

The first call will use CLOCK_MONOTONIC and wait correctly for the full 5 minutes.
The second call will use CLOCK_REALTIME and immediately time out. Because that date call will jump 5 minutes into the future.

I'm on Ubuntu 22.04, looks like this for me:

$ ./pthread_cond_timedwait monotonic &  sleep 2s; sudo date -s "$(date -Rd '5 minutes')"
[13] 25386
starting...
using CLOCK_MONOTONIC

it just waits, and

$ ./pthread_cond_timedwait &  sleep 2s; sudo date -s "$(date -Rd '5 minutes')"
[14] 25395
starting...
pthread_cond_timedwait Connection timed out
[14]+  Exit 1                  ./pthread_cond_timedwait

errors out immediately.

What multi-slot reader do you use?

It doesn't matter, it should be an issue with every multi-slot reader, because it's really just a POSIX API caveat. You have to change the time while waiting in the pthread_cond_timedwait to close or even after the abstime value and you will get an early timeout with CLOCK_REALTIME. And as i said it's a known issue, that's why libusb moved to CLOCK_MONOTONIC too. I linked you the exact commit with the explanation in it.

[LudovicRousseau]

I know the problem is generic and not related to one specific reader.
I only have 10 multi-slots readers in my list that are subject to this problem.
https://ccid.apdu.fr/select_readers/?bMaxCCIDBusySlots%E2%89%A52

I guess your reader is NOT in this list. Right?