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

[Scott Godin]

I have committed a fix to SVN trunk for this.  Thanks again!

Scott


On Mon, Feb 10, 2014 at 10:05 AM, Scott Godin <sgodin at sipspectrum.com>wrote:

> 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/20140211/87568749/attachment.htm>