Re: [reSIProcate] race condition in resip::Log::timestamp

[Scott Godin <sgodin@xxxxxxxxxxxxxxx>]

Nice catch.  Thanks for the details report.  Sounds to me that we need to use localtime_r instead.

Scott

On Mon, Feb 10, 2014 at 7:21 AM, <dwest1975@xxxxxxx> wrote:

Hi,

I'm using resiprocate library version 1.8.8 under Oracle Linux Server 6.5 and see the following race condition under Helgrind:

==8418== 88 errors in context 96 of 102:

==8418== ----------------------------------------------------------------

==8418== 

==8418== Lock at 0x7FEFDB008 was first observed

==8418==    at 0x4A0BDA3: pthread_mutex_init (hg_intercepts.c:429)

==8418==    by 0x3BB0566DDA: resip::SipStack::SipStack(resip::Security*, std::vector<resip::GenericIPAddress, std::allocat

or<resip::GenericIPAddress> > const&, resip::AsyncProcessHandler*, bool, void (*)(int, int, char const*, int), resip::Comp

ression*, resip::FdPollGrp*) (SipStack.cxx:97)

==8418==    by 0x6B5D52: main (ProxyDaemon.cxx:831)

==8418== 

==8418== Possible data race during write of size 4 at 0x7068E88 by thread #18

==8418== Locks held: none

==8418==    at 0x4A063C0: free (vg_replace_malloc.c:446)

==8418==    by 0x3BA3A9DBE8: tzset_internal (tzset.c:435)

==8418==    by 0x3BA3A9DD68: __tz_convert (tzset.c:624)

==8418==    by 0x3BAFC3B63A: resip::Log::timestamp(resip::Data&) (Log.cxx:437)

==8418==    by 0x3BAFC3CF43: resip::Log::tags(resip::Log::Level, resip::Subsystem const&, char const*, int, std::ostream&)

 (Log.cxx:388)

==8418==    by 0x3BAFC3D22C: resip::Log::Guard::Guard(resip::Log::Level, resip::Subsystem const&, char const*, int) (Log.c

xx:731)

==8418==    by 0x3BB058E5CB: resip::TransportSelector::determineSourceInterface(resip::SipMessage*, resip::Tuple const&) c

onst (TransportSelector.cxx:747)

==8418==    by 0x3BB05914C7: resip::TransportSelector::transmit(resip::SipMessage*, resip::Tuple&, resip::SendData*) (Tran

sportSelector.cxx:851)

==8418==    by 0x3BB058662F: resip::TransactionState::process(resip::TransactionController&, resip::TransactionMessage*) (TransactionState.cxx:406)

==8418==    by 0x3BB0577B0B: resip::TransactionController::process(int) (TransactionController.cxx:141)

==8418==    by 0x3BB056A260: resip::TransactionControllerThread::thread() (TransactionControllerThread.hxx:30)

==8418==    by 0x3BAFC47359: threadIfThreadWrapper (ThreadIf.cxx:51)

==8418== 

==8418== This conflicts with a previous write of size 4 by thread #21

==8418== Locks held: 1, at address 0x7FEFDB008

==8418==    at 0x4A063C0: free (vg_replace_malloc.c:446)

==8418==    by 0x3BA3A9DBE8: tzset_internal (tzset.c:435)

==8418==    by 0x3BA3A9DD68: __tz_convert (tzset.c:624)

==8418==    by 0x3BAFC3B63A: resip::Log::timestamp(resip::Data&) (Log.cxx:437)

==8418==    by 0x3BAFC3CF43: resip::Log::tags(resip::Log::Level, resip::Subsystem const&, char const*, int, std::ostream&) (Log.cxx:388)

==8418==    by 0x3BAFC3D22C: resip::Log::Guard::Guard(resip::Log::Level, resip::Subsystem const&, char const*, int) (Log.cxx:731)

==8418==    by 0x3BB057255E: resip::TuSelectorTimerQueue::add(unsigned int, resip::Message*) (TimerQueue.cxx:124)

==8418==    by 0x3BB0566088: resip::SipStack::postMS(std::auto_ptr<resip::ApplicationMessage>, unsigned int, resip::TransactionUser*) (SipStack.cxx:697)

Apparently localtime() is used in resip::Log::timestamp:

    420    if (result == -1)

    421    {

    422       /* If we can't get the time of day, don't print a timestamp.

    423          Under Unix, this will never happen:  gettimeofday can fail only

    424          if the timezone is invalid which it can't be, since it is

    425          uninitialized]or if tv or tz are invalid pointers. */

    426       datebuf [0] = 0;

    427    }

    428    else

    429    {

    430       /* The tv_sec field represents the number of seconds passed since

    431          the Epoch, which is exactly the argument gettimeofday needs. */

    432       const time_t timeInSeconds = (time_t) tv.tv_sec;

    433       strftime (datebuf,

    434                 datebufSize,

    435                 "%Y%m%d-%H%M%S", /* guaranteed to fit in 256 chars,

    436                                     hence don't check return code */

    437                 localtime (&timeInSeconds));

    438    }

Which is not thread-safe according to 'man 3 localtime':

       The four functions asctime(), ctime(), gmtime() and localtime() return a pointer to  static  data  and

       hence  are not thread-safe.  Thread-safe versions asctime_r(), ctime_r(), gmtime_r() and localtime_r()

       are specified by SUSv2, and available since libc 5.2.5.

Could you please comment this Helgrind report? Is it "fixable" from your side?

Thank you!

Dean

_______________________________________________
resiprocate-devel mailing list
resiprocate-devel@xxxxxxxxxxxxxxx
https://list.resiprocate.org/mailman/listinfo/resiprocate-devel