std::timed_mutex::try_lock_for fails immediately

Question

I'm using a std::timed_mutex for the first time and it's not behaving the way I expect. It appears to fail immediately instead of waiting for the mutex. I'm providing the lock timeout in milliseconds (as shown here http://www.cplusplus.com/reference/mutex/timed_mutex/try_lock_for/). But the call to try_lock_for() fails right away.

Here's the class that handles locking and unlocking the mutex:

  const unsigned int DEFAULT_MUTEX_WAIT_TIME_MS = 5 * 60 * 1000;

  class ScopedTimedMutexLock
  {
  public:
     ScopedTimedMutexLock(std::timed_mutex* sourceMutex, unsigned int numWaitMilliseconds=DEFAULT_MUTEX_WAIT_TIME_MS)
        m_mutex(sourceMutex)
     {
        if( !m_mutex->try_lock_for( std::chrono::milliseconds(numWaitMilliseconds) ) )
        {
           std::string message = "Timeout attempting to acquire mutex lock for ";
           message += Conversion::toString(numWaitMilliseconds);
           message += "ms";
           throw MutexException(message);
        }
     }
     ~ScopedTimedMutexLock()
     {
        m_mutex->unlock();
     }
  private:
     std::timed_mutex* m_mutex;
  };

And this is where it's being used:

  void  CommandService::Process( RequestType& request )
  {
     unsigned long callTime =
        std::chrono::duration_cast< std::chrono::milliseconds >(
           std::chrono::system_clock::now().time_since_epoch()
        ).count();

     try
     {
        ScopedTimedMutexLock lock( m_classMutex, request.getLockWaitTimeMs(DEFAULT_MUTEX_WAIT_TIME_MS) );
        // ... command processing code goes here
     }
     catch( MutexException& mutexException )
     {
        unsigned long catchTime =
           std::chrono::duration_cast< std::chrono::milliseconds >(
              std::chrono::system_clock::now().time_since_epoch()
           ).count();
        cout << "The following error occured while attempting to process command"
             << "\n   call  time: " << callTime
             << "\n   catch time: " << catchTime;
        cout << mutexException.description();
     }
  }

Here's the console output:

The following error occured while attempting to process command
   call  time: 1131268914
   catch time: 1131268914
Timeout attempting to acquire mutex lock for 300000ms

Any idea where this is going wrong? Is the conversion to std::chrono::milliseconds correct? How do I make try_lock_for() wait for the lock?

ADDITIONAL INFO: The call to try_lock_for() didn't always fail immediately. Many times the call acquired the lock and everything worked as expected. The failures I was seeing were intermittent. See my answer below for details about why this was failing.

Answer 1

The root cause of the problem is mentioned in the description for try_lock_for() at http://en.cppreference.com/w/cpp/thread/timed_mutex/try_lock_for. Near the end of the description it says:

As with try_lock(), this function is allowed to fail spuriously and return false even if the mutex was not locked by any other thread at some point during timeout_duration.

I naively assumed there were only two possible outcomes: (1) the function acquires the lock within the time period, or (2) the function fails after the wait time has elapsed. But there is another possibility, (3) the function fails after a relatively short time for no specified reason. TL;DR, my bad.

I solved the problem by rewriting the ScopedTimedMutexLock constructor to loop on try_lock() until the lock is acquired or the wait time limit is exceeded.

 ScopedTimedMutexLock(std::timed_mutex* sourceMutex, unsigned int numWaitMilliseconds=DEFAULT_MUTEX_WAIT_TIME_MS)
    m_mutex(sourceMutex)
 {
    const unsigned SLEEP_TIME_MS = 5;
    bool isLocked = false;
    unsigned long startMS = now();
    while( now() - startMS < numWaitMilliseconds && !isLocked )
    {
       isLocked = m_sourceMutex->try_lock();
       if( !isLocked )
       {
          std::this_thread::sleep_for(
              std::chrono::milliseconds(SLEEP_TIME_MS));
       }
    }
    if( !isLocked )
    {
       std::string message = "Timeout attempting to acquire mutex lock for ";
       message += Conversion::toString(numWaitMilliseconds);
       message += "ms";
       throw MutexException(message);
    }
 }

Where now() is defined like this:

  private:
     unsigned long now() {
        return std::chrono::duration_cast< std::chrono::milliseconds >(
            std::chrono::system_clock::now().time_since_epoch() ).count();
     }