[Pacemaker] Pengine assert in qb_log_from_external_source()

Thu Nov 22 23:43:27 UTC 2012

On Fri, Nov 23, 2012 at 10:20 AM, Angus Salkeld <asalkeld at redhat.com> wrote:
> On 22/11/12 14:37 +0300, Vladislav Bogdanov wrote:
>>
>> 22.11.2012 14:18, Angus Salkeld wrote:
>>>
>>> On 22/11/12 11:48 +1100, Andrew Beekhof wrote:
>>>>
>>>> On Tue, Nov 20, 2012 at 5:32 PM, Vladislav Bogdanov
>>>> <bubble at hoster-ok.com> wrote:
>>>>>
>>>>> Hi,
>>>>>
>>>>> Running 06229e9 with qb 0.14.3, and noticed following assert() in trace
>>>>> logging path:
>>>>>
>>>>> #0  0x00007f40451688a5 in raise () from /lib64/libc.so.6
>>>>> #1  0x00007f404516a085 in abort () from /lib64/libc.so.6
>>>>> #2  0x00007f4045161a1e in __assert_fail_base () from /lib64/libc.so.6
>>>>> #3  0x00007f4045161ae0 in __assert_fail () from /lib64/libc.so.6
>>>>> #4  0x00007f40445e918b in ?? () from /usr/lib64/libqb.so.0
>>>>> #5  0x00007f40445e9385 in qb_log_dcs_get () from /usr/lib64/libqb.so.0
>>>>> #6  0x00007f40445e7949 in qb_log_callsite_get () from
>
>
> Any chance of getting some debug symbols from libqb?

He did that in the followup below.

>
> ./configure --enable-debug
>
> -Angus
>
>
>>>>> /usr/lib64/libqb.so.0
>>>>> #7  0x00007f40445e7e4b in qb_log_from_external_source () from
>>>>> /usr/lib64/libqb.so.0
>>>>> #8  0x00007f4046fb12f5 in dump_node_scores_worker (level=9,
>>>>> file=0x7f4046d8e1bf "native.c", function=0x7f4046d90210
>>>>> "native_choose_node", line=148,
>>>>>     rsc=0x2411a70, comment=0x7f4046d8e4a1 "Post-utilization",
>>>>> nodes=0x26bede0) at utils.c:189
>>>>> #9  0x00007f4046d6ba65 in native_choose_node (rsc=0x2411a70,
>>>>> prefer=0x2c35b20, data_set=0x7fff24356dc0) at native.c:148
>>>>> #10 native_color (rsc=0x2411a70, prefer=0x2c35b20,
>>>>> data_set=0x7fff24356dc0) at native.c:531
>>>>> #11 0x00007f4046d7b40c in color_instance (rsc=0x2411a70,
>>>>> prefer=0x2c35b20, all_coloc=<value optimized out>,
>>>>> data_set=0x7fff24356dc0) at clone.c:430
>>>>> #12 0x00007f4046d7f459 in clone_color (rsc=0x25cde30, prefer=<value
>>>>> optimized out>, data_set=0x7fff24356dc0) at clone.c:578
>>>>> #13 0x00007f4046d6b020 in native_color (rsc=0x2624a50, prefer=0x0,
>>>>> data_set=0x7fff24356dc0) at native.c:459
>>>>> #14 0x00007f4046d5cc2f in stage5 (data_set=0x7fff24356dc0) at
>>>>> allocate.c:1130
>>>>> #15 0x00007f4046d53b3d in do_calculations (data_set=0x7fff24356dc0,
>>>>> xml_input=<value optimized out>, now=<value optimized out>) at
>>>>> pengine.c:247
>>>>> #16 0x00007f4046d54722 in process_pe_message (msg=0x2c24650,
>>>>> xml_data=0x2c08a50, sender=0x2337350) at pengine.c:126
>>>>> #17 0x000000000040124e in pe_ipc_dispatch (c=0x2337350, data=<value
>>>>> optimized out>, size=<value optimized out>) at main.c:75
>>>>> #18 0x00007f40445e3954 in ?? () from /usr/lib64/libqb.so.0
>>>>> #19 0x00007f40445e3ca4 in qb_ipcs_dispatch_connection_request () from
>>>>> /usr/lib64/libqb.so.0
>>>>> #20 0x00007f40471ef1c0 in gio_read_socket (gio=<value optimized out>,
>>>>> condition=G_IO_IN, data=0x2336b50) at mainloop.c:367
>>>>> #21 0x00007f4044a77f0e in g_main_context_dispatch () from
>>>>> /lib64/libglib-2.0.so.0
>>>>> #22 0x00007f4044a7b938 in ?? () from /lib64/libglib-2.0.so.0
>>>>> #23 0x00007f4044a7bd55 in g_main_loop_run () from
>>>>> /lib64/libglib-2.0.so.0
>>>>> #24 0x00000000004014c8 in main (argc=1, argv=0x7fff24357398) at
>>>>> main.c:159
>>>>>
>>>>>
>>>>>
>>>>> #4 should be in _log_dcs_new_cs(), I do not see another calls from
>>>>> qb_log_from_external_source() which have assert() inside.
>>>>>
>>>>> Is this pacemaker or qb problem?
>>>>
>>>>
>>>> I'd be inclined to claim libqb at this point.
>>>
>>>
>>> You would wouldn't you;)
>>>
>>> So we have had a problem with ubuntu having some strange
>>> linking/stripping
>>> that has caused some problems with libqb logging.
>>>
>>> So to confirm (if this is a reproducible bug) rebuild with:
>>>
>>>     ./configure ac_cv_link_attribute_section=no
>>
>>
>> I'll do.
>> This seems to be reproducible and happens 1-2 times per day.
>>
>> OS is Centos6 x86_64 (latest updates)
>>
>> Backtrace with libqb debuginfo:
>>
>> #0  0x00007fa2f682f8a5 in raise () from /lib64/libc.so.6
>> #1  0x00007fa2f6831085 in abort () from /lib64/libc.so.6
>> #2  0x00007fa2f6828a1e in __assert_fail_base () from /lib64/libc.so.6
>> #3  0x00007fa2f6828ae0 in __assert_fail () from /lib64/libc.so.6
>> #4  0x00007fa2f5cb018b in _log_dcs_new_cs (function=0x7fa2f84571e0
>> "native_color", filename=0x7fa2f84551bf "native.c",
>>    format=0x7fa2f8689c90 "%s: %s allocation score on %s: %s",
>> priority=<value optimized out>, lineno=500, tags=0) at log_dcs.c:70
>> #5  0x00007fa2f5cb0385 in qb_log_dcs_get (newly_created=0x7fffd238d6ec,
>> function=<value optimized out>, filename=<value optimized out>,
>>    format=<value optimized out>, priority=8 '\b', lineno=<value
>> optimized out>, tags=0) at log_dcs.c:146
>> #6  0x00007fa2f5cae949 in qb_log_callsite_get (function=<value optimized
>> out>, filename=<value optimized out>, format=<value optimized out>,
>>    priority=<value optimized out>, lineno=<value optimized out>,
>> tags=0) at log.c:256
>> #7  0x00007fa2f5caee4b in qb_log_from_external_source (function=<value
>> optimized out>, filename=<value optimized out>, format=<value optimized
>> out>,
>>    priority=<value optimized out>, lineno=<value optimized out>,
>> tags=<value optimized out>) at log.c:331
>> #8  0x00007fa2f86782f5 in dump_node_scores_worker (level=8,
>> file=0x7fa2f84551bf "native.c", function=0x7fa2f84571e0 "native_color",
>> line=500, rsc=0xd655a0,
>>    comment=0x7fa2f84571ed "native_color", nodes=0xf4ff70) at utils.c:189
>> #9  0x00007fa2f8432247 in native_color (rsc=0xd655a0, prefer=0xfcd6e0,
>> data_set=0x7fffd238dca0) at native.c:499
>> #10 0x00007fa2f844240c in color_instance (rsc=0xd655a0, prefer=0xfcd6e0,
>> all_coloc=<value optimized out>, data_set=0x7fffd238dca0) at clone.c:430
>> #11 0x00007fa2f8446459 in clone_color (rsc=0x10b6a30, prefer=<value
>> optimized out>, data_set=0x7fffd238dca0) at clone.c:578
>> #12 0x00007fa2f8432020 in native_color (rsc=0xf0cd00, prefer=0x0,
>> data_set=0x7fffd238dca0) at native.c:459
>> #13 0x00007fa2f8423c2f in stage5 (data_set=0x7fffd238dca0) at
>> allocate.c:1130
>> #14 0x00007fa2f841ab3d in do_calculations (data_set=0x7fffd238dca0,
>> xml_input=<value optimized out>, now=<value optimized out>) at
>> pengine.c:247
>> #15 0x00007fa2f841b722 in process_pe_message (msg=0x15e6d20,
>> xml_data=0x15d6ba0, sender=0xcf0350) at pengine.c:126
>> #16 0x000000000040124e in pe_ipc_dispatch (c=0xcf0350, data=<value
>> optimized out>, size=<value optimized out>) at main.c:75
>> #17 0x00007fa2f5caa954 in _process_request_ (c=0xcf0350, ms_timeout=10)
>> at ipcs.c:647
>> #18 0x00007fa2f5caaca4 in qb_ipcs_dispatch_connection_request (fd=<value
>> optimized out>, revents=<value optimized out>, data=0xcf0350) at
>> ipcs.c:755
>> #19 0x00007fa2f88b61c0 in gio_read_socket (gio=<value optimized out>,
>> condition=G_IO_IN, data=0xcefb50) at mainloop.c:367
>> #20 0x00007fa2f613ef0e in g_main_context_dispatch () from
>> /lib64/libglib-2.0.so.0
>> #21 0x00007fa2f6142938 in ?? () from /lib64/libglib-2.0.so.0
>> #22 0x00007fa2f6142d55 in g_main_loop_run () from /lib64/libglib-2.0.so.0
>> #23 0x00000000004014c8 in main (argc=1, argv=0x7fffd238e278) at main.c:159
>>
>> log_dcs.c:70 is assert(rc == 0);
>> So, qb_array_index() returns 0
>>
>> Couldn't that be some integer overflow?
>>
>> Vladislav
>>
>>
>> _______________________________________________
>> Pacemaker mailing list: Pacemaker at oss.clusterlabs.org
>> http://oss.clusterlabs.org/mailman/listinfo/pacemaker
>>
>> Project Home: http://www.clusterlabs.org
>> Getting started: http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf
>> Bugs: http://bugs.clusterlabs.org
>
>
> _______________________________________________
> Pacemaker mailing list: Pacemaker at oss.clusterlabs.org
> http://oss.clusterlabs.org/mailman/listinfo/pacemaker
>
> Project Home: http://www.clusterlabs.org
> Getting started: http://www.clusterlabs.org/doc/Cluster_from_Scratch.pdf
> Bugs: http://bugs.clusterlabs.org