[Home]

Summary:ASTERISK-25782: data race on logger
Reporter:Badalian Vyacheslav (slavon)Labels:
Date Opened:2016-02-11 23:15:12.000-0600Date Closed:2016-10-30 13:53:47
Priority:MinorRegression?
Status:Closed/CompleteComponents:
Versions:13.7.2 Frequency of
Occurrence
Related
Issues:
Environment:[root@vm-asterisk04t asterisk]# git branch -v * master a394865 Merge "Resources/res_phoneprov: fix memory leak and heap-use-after-free" Attachments:( 0) ASTERISK-25782.patch
Description:{code}
WARNING: ThreadSanitizer: data race (pid=15278)
 Read of size 4 at 0x7fcb842ff800 by thread T40 (mutexes: write M9761):
   #0 ast_log_full /root/asterisk/main/logger.c:1922 (asterisk+0x00000050f270)
   #1 ast_log /root/asterisk/main/logger.c:1991 (asterisk+0x000000510d7f)
   #2 stun_monitor_request /root/asterisk/res/res_stun_monitor.c:151 (res_stun_monitor.so+0x0000000027d7)
   #3 ast_sched_runq /root/asterisk/main/sched.c:748 (asterisk+0x00000061019e)
   #4 sched_run /root/asterisk/main/sched.c:160 (asterisk+0x00000060bc1a)
   #5 dummy_start /root/asterisk/main/utils.c:1232 (asterisk+0x0000006b6674)
   #6 <null> <null> (libtsan.so.0+0x000000023659)

 Previous write of size 4 at 0x7fcb842ff800 by main thread:
   [failed to restore the stack]

 Location is global 'global_logmask' of size 4 at 0x7fcb842ff800 (asterisk+0x000000b7a800)

 Mutex M9761 (0x7fcb749fbc20) created at:
   #0 pthread_mutex_init <null> (libtsan.so.0+0x000000028645)
   #1 __ast_pthread_mutex_init /root/asterisk/main/lock.c:149 (asterisk+0x000000503c43)
   #2 load_module /root/asterisk/res/res_stun_monitor.c:465 (res_stun_monitor.so+0x000000003b79)
   #3 start_resource /root/asterisk/main/loader.c:1015 (asterisk+0x0000004ff12f)
   #4 load_resource_list /root/asterisk/main/loader.c:1213 (asterisk+0x000000500c7c)
   #5 load_modules /root/asterisk/main/loader.c:1361 (asterisk+0x000000501aba)
   #6 asterisk_daemon /root/asterisk/main/asterisk.c:4659 (asterisk+0x0000002d6e5d)
   #7 main /root/asterisk/main/asterisk.c:4230 (asterisk+0x0000002d5cfd)

 Thread T40 (tid=15799, running) created by main thread at:
   #0 pthread_create <null> (libtsan.so.0+0x000000027b07)
   #1 ast_pthread_create_stack /root/asterisk/main/utils.c:1285 (asterisk+0x0000006b6abd)
   #2 ast_sched_start_thread /root/asterisk/main/sched.c:207 (asterisk+0x00000060c24b)
   #3 stun_start_monitor /root/asterisk/res/res_stun_monitor.c:246 (res_stun_monitor.so+0x000000002cf1)
   #4 __reload /root/asterisk/res/res_stun_monitor.c:436 (res_stun_monitor.so+0x000000003a47)
   #5 load_module /root/asterisk/res/res_stun_monitor.c:467 (res_stun_monitor.so+0x000000003b99)
   #6 start_resource /root/asterisk/main/loader.c:1015 (asterisk+0x0000004ff12f)
   #7 load_resource_list /root/asterisk/main/loader.c:1213 (asterisk+0x000000500c7c)
   #8 load_modules /root/asterisk/main/loader.c:1361 (asterisk+0x000000501aba)
   #9 asterisk_daemon /root/asterisk/main/asterisk.c:4659 (asterisk+0x0000002d6e5d)
   #10 main /root/asterisk/main/asterisk.c:4230 (asterisk+0x0000002d5cfd)

SUMMARY: ThreadSanitizer: data race /root/asterisk/main/logger.c:1922 ast_log_full
==================

{code}
Comments:By: Asterisk Team (asteriskteam) 2016-02-11 23:15:14.243-0600

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: Corey Farrell (coreyfarrell) 2016-02-12 09:03:39.496-0600

As with ASTERISK-25783 I'd like to know if this problem can be solved by simply using a volatile.  For this function I'm not keen on using a lock here, {{ast_log_full}} is run so often that we need to be concerned about performance penalty of any additional checks.  Especially since the purpose of this conditional is to avoid creation of a {{struct logmsg}} when it will not be used anyways.
By: Badalian Vyacheslav (slavon) 2016-02-12 10:53:23.826-0600

can you give patch to test? I quickly check
By: Badalian Vyacheslav (slavon) 2016-02-12 11:51:25.148-0600

volatile does not help...

after patch
{code}
Asterisk Ready.
*CLI> ==================
WARNING: ThreadSanitizer: data race (pid=18295)
 Read of size 4 at 0x7fe27a413800 by thread T42 (mutexes: write M9761):
   #0 ast_log_full /root/asterisk/main/logger.c:1922 (asterisk+0x00000050f270)
   #1 ast_log /root/asterisk/main/logger.c:1991 (asterisk+0x000000510d7f)
   #2 stun_monitor_request /root/asterisk/res/res_stun_monitor.c:151 (res_stun_monitor.so+0x0000000027d7)
   #3 ast_sched_runq /root/asterisk/main/sched.c:748 (asterisk+0x00000061019e)
   #4 sched_run /root/asterisk/main/sched.c:160 (asterisk+0x00000060bc1a)
   #5 dummy_start /root/asterisk/main/utils.c:1232 (asterisk+0x0000006b66a0)
   #6 <null> <null> (libtsan.so.0+0x000000023659)

 Previous write of size 4 at 0x7fe27a413800 by main thread:
   [failed to restore the stack]

 Location is global 'global_logmask' of size 4 at 0x7fe27a413800 (asterisk+0x000000b7a800)

 Mutex M9761 (0x7fe26aab4c20) created at:
   #0 pthread_mutex_init <null> (libtsan.so.0+0x000000028645)
   #1 __ast_pthread_mutex_init /root/asterisk/main/lock.c:149 (asterisk+0x000000503c43)
   #2 load_module /root/asterisk/res/res_stun_monitor.c:465 (res_stun_monitor.so+0x000000003b79)
   #3 start_resource /root/asterisk/main/loader.c:1015 (asterisk+0x0000004ff12f)
   #4 load_resource_list /root/asterisk/main/loader.c:1213 (asterisk+0x000000500c7c)
   #5 load_modules /root/asterisk/main/loader.c:1361 (asterisk+0x000000501aba)
   #6 asterisk_daemon /root/asterisk/main/asterisk.c:4659 (asterisk+0x0000002d6e5d)
   #7 main /root/asterisk/main/asterisk.c:4230 (asterisk+0x0000002d5cfd)

 Thread T42 (tid=18818, running) created by main thread at:
   #0 pthread_create <null> (libtsan.so.0+0x000000027b07)
   #1 ast_pthread_create_stack /root/asterisk/main/utils.c:1285 (asterisk+0x0000006b6ae9)
   #2 ast_sched_start_thread /root/asterisk/main/sched.c:207 (asterisk+0x00000060c24b)
   #3 stun_start_monitor /root/asterisk/res/res_stun_monitor.c:246 (res_stun_monitor.so+0x000000002cf1)
   #4 __reload /root/asterisk/res/res_stun_monitor.c:436 (res_stun_monitor.so+0x000000003a47)
   #5 load_module /root/asterisk/res/res_stun_monitor.c:467 (res_stun_monitor.so+0x000000003b99)
   #6 start_resource /root/asterisk/main/loader.c:1015 (asterisk+0x0000004ff12f)
   #7 load_resource_list /root/asterisk/main/loader.c:1213 (asterisk+0x000000500c7c)
   #8 load_modules /root/asterisk/main/loader.c:1361 (asterisk+0x000000501aba)
   #9 asterisk_daemon /root/asterisk/main/asterisk.c:4659 (asterisk+0x0000002d6e5d)
   #10 main /root/asterisk/main/asterisk.c:4230 (asterisk+0x0000002d5cfd)

SUMMARY: ThreadSanitizer: data race /root/asterisk/main/logger.c:1922 ast_log_full
==================

{code}