[Home]

Summary:ASTERISK-25773: ast flags macros broke atomic thread safe
Reporter:Badalian Vyacheslav (slavon)Labels:
Date Opened:2016-02-11 22:13:01.000-0600Date Closed:2016-10-30 13:54:01
Priority:MajorRegression?
Status:Closed/CompleteComponents:
Versions:11.21.2 13.7.1 13.7.2 Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:defines like this broke atomic thread safe
{code}
#define ast_set_flag(p,flag)            do { \
                                       typeof ((p)->flags) __p = (p)->flags; \
                                       typeof (__unsigned_int_flags_dummy) __x = 0; \
                                       (void) (&__p == &__x); \
                                       ((p)->flags |= (flag)); \
                                       } while(0)
{code}

for add, xor, sub and other you must do for old gcc:
https://gcc.gnu.org/onlinedocs/gcc/_005f_005fsync-Builtins.html
or for new gcc:
https://gcc.gnu.org/onlinedocs/gcc-4.4.5/gcc/Atomic-Builtins.html

or you get data race
{code}
==================
WARNING: ThreadSanitizer: data race (pid=24710)
 Write of size 4 at 0x7f5ec5941810 by main thread:
   #0 asterisk_daemon /root/asterisk/main/asterisk.c:4691 (asterisk+0x0000002d6ffe)
   #1 main /root/asterisk/main/asterisk.c:4230 (asterisk+0x0000002d5cfd)

 Previous read of size 4 at 0x7f5ec5941810 by thread T1:
   #0 queued_set_size /root/asterisk/main/threadpool.c:825 (asterisk+0x000000694b51)
   #1 ast_taskprocessor_execute /root/asterisk/main/taskprocessor.c:850 (asterisk+0x00000067f1bb)
   #2 default_tps_processing_function /root/asterisk/main/taskprocessor.c:183 (asterisk+0x00000067b1c4)
   #3 dummy_start /root/asterisk/main/utils.c:1232 (asterisk+0x0000006b6674)
   #4 <null> <null> (libtsan.so.0+0x000000023659)

 Location is global 'ast_options' of size 4 at 0x7f5ec5941810 (asterisk+0x000000a07810)

 Thread T1 (tid=25192, 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 default_listener_start /root/asterisk/main/taskprocessor.c:200 (asterisk+0x00000067b33a)
   #3 __allocate_taskprocessor /root/asterisk/main/taskprocessor.c:682 (asterisk+0x00000067e298)
   #4 ast_taskprocessor_get /root/asterisk/main/taskprocessor.c:728 (asterisk+0x00000067e4c1)
   #5 threadpool_alloc /root/asterisk/main/threadpool.c:402 (asterisk+0x00000069266e)
   #6 ast_threadpool_create /root/asterisk/main/threadpool.c:894 (asterisk+0x000000695202)
   #7 ast_sorcery_init /root/asterisk/main/sorcery.c:504 (asterisk+0x00000061d926)
   #8 asterisk_daemon /root/asterisk/main/asterisk.c:4383 (asterisk+0x0000002d64cb)
   #9 main /root/asterisk/main/asterisk.c:4230 (asterisk+0x0000002d5cfd)

SUMMARY: ThreadSanitizer: data race /root/asterisk/main/asterisk.c:4691 asterisk_daemon
{code}

{code}
==================
WARNING: ThreadSanitizer: data race (pid=25310)
 Write of size 4 at 0x7fec0ba42810 by main thread:
   #0 asterisk_daemon /root/asterisk/main/asterisk.c:4691 (asterisk+0x0000002d6ffe)
   #1 main /root/asterisk/main/asterisk.c:4230 (asterisk+0x0000002d5cfd)

 Previous read of size 4 at 0x7fec0ba42810 by thread T33:
   #0 log_forwarder /root/asterisk/res/res_pjproject.c:105 (res_pjproject.so+0x000000002001)
   #1 pj_log ../src/pj/log.c:478 (libpj.so.2+0x000000015b9a)
   #2 thread_main ../src/pj/os_core_unix.c:541 (libpj.so.2+0x00000000f5f9)

 Location is global 'ast_options' of size 4 at 0x7fec0ba42810 (asterisk+0x000000a07810)

 Thread T33 (tid=25824, running) created by main thread at:
   #0 pthread_create <null> (libtsan.so.0+0x000000027b07)
   #1 pj_thread_create ../src/pj/os_core_unix.c:634 (libpj.so.2+0x00000000f448)
   #2 start_resource /root/asterisk/main/loader.c:1015 (asterisk+0x0000004ff12f)
   #3 load_resource_list /root/asterisk/main/loader.c:1213 (asterisk+0x000000500c7c)
   #4 load_modules /root/asterisk/main/loader.c:1366 (asterisk+0x000000501ade)
   #5 asterisk_daemon /root/asterisk/main/asterisk.c:4659 (asterisk+0x0000002d6e5d)
   #6 main /root/asterisk/main/asterisk.c:4230 (asterisk+0x0000002d5cfd)

SUMMARY: ThreadSanitizer: data race /root/asterisk/main/asterisk.c:4691 asterisk_daemon
==================
{code}

{code}
==================
WARNING: ThreadSanitizer: data race (pid=26400)
 Write of size 8 at 0x7f9d5ed33ae0 by main thread:
   #0 asterisk_daemon /root/asterisk/main/asterisk.c:4682 (asterisk+0x0000002d6f45)
   #1 main /root/asterisk/main/asterisk.c:4230 (asterisk+0x0000002d5cfd)

 Previous read of size 8 at 0x7f9d5ed33ae0 by thread T6 (mutexes: read M10):
   #0 console_verboser /root/asterisk/main/asterisk.c:2199 (asterisk+0x0000002c8ac9)
   #1 logger_print_normal /root/asterisk/main/logger.c:1477 (asterisk+0x00000050cd4a)
   #2 logger_thread /root/asterisk/main/logger.c:1615 (asterisk+0x00000050dfa2)
   #3 dummy_start /root/asterisk/main/utils.c:1232 (asterisk+0x0000006b6674)
   #4 <null> <null> (libtsan.so.0+0x000000023659)

 Location is global 'consolethread' of size 8 at 0x7f9d5ed33ae0 (asterisk+0x000000a08ae0)

 Mutex M10 (0x7f9d5eea5a10) created at:
   #0 pthread_rwlock_wrlock <null> (libtsan.so.0+0x0000000293ad)
   #1 __ast_rwlock_wrlock /root/asterisk/main/lock.c:1018 (asterisk+0x00000050420f)
   #2 ast_register_verbose /root/asterisk/main/logger.c:2281 (asterisk+0x0000005124ba)
   #3 print_intro_message /root/asterisk/main/asterisk.c:3782 (asterisk+0x0000002d2dd6)
   #4 asterisk_daemon /root/asterisk/main/asterisk.c:4321 (asterisk+0x0000002d625b)
   #5 main /root/asterisk/main/asterisk.c:4230 (asterisk+0x0000002d5cfd)

 Thread T6 (tid=26894, 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 init_logger /root/asterisk/main/logger.c:1698 (asterisk+0x00000050e33e)
   #3 asterisk_daemon /root/asterisk/main/asterisk.c:4457 (asterisk+0x0000002d6799)
   #4 main /root/asterisk/main/asterisk.c:4230 (asterisk+0x0000002d5cfd)

SUMMARY: ThreadSanitizer: data race /root/asterisk/main/asterisk.c:4682 asterisk_daemon
==================
{code}
Comments:By: Asterisk Team (asteriskteam) 2016-02-11 22:13:04.192-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:39:28.682-0600

The line numbers in your backtraces do not match my copy of main/asterisk.c.  What tag/version or commit produced this?

In theory {{ast_set_flag(&ast_options, value)}} should only be run during startup on the main thread before any other threads are spawned.  {{ast_set_flag}} is used by other parts of Asterisk under protection of a lock.  So I'm not sure we'll want to change {{ast_set_flag}}, probably better to treat {{ast_options}} as immutable once we start spawning threads.  We would probably need to move the flag for fullybooted out of {{ast_options}}, but that would be an ABI change so it's not possible for 13.
By: Badalian Vyacheslav (slavon) 2016-02-12 10:49:31.893-0600

[root@vm-asterisk04t asterisk]# git branch -v
* master a394865 Merge "Resources/res_phoneprov: fix memory leak and heap-use-after-free"

By: Corey Farrell (coreyfarrell) 2016-02-12 13:25:24.674-0600

On closer look we have 2 issues here (the first two backtraces are the issue).

# We use ast_set_flag to set fullybooted.  We probably do need an atomic version of ast_set_flag for use here.  I'm not sure it would be good to make ast_set_flag atomic as most uses of it are protected by a lock for other reasons anyways.
# consolethread is set a bit late in the initialization.  I'm thinking it should be set before we run ast_register_verbose(console_verbose).  This would require signal handler initialization and temporarily masking to be moved earlier in the initialization too.  Messing with the initialization order can get risky, it's possible we might fix this part in master only.
By: Badalian Vyacheslav (slavon) 2016-02-12 13:28:07.064-0600

Ok... looks like duplicate of other created issues... lets patch them and i will test :)