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

[Scott Godin]

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 at hush.ai> 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 at resiprocate.org
> https://list.resiprocate.org/mailman/listinfo/resiprocate-devel
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://list.resiprocate.org/pipermail/resiprocate-devel/attachments/20140210/80191208/attachment.htm>