RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1451170 - Crash in lrmd
Summary: Crash in lrmd
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: pacemaker
Version: 7.3
Hardware: Unspecified
OS: Unspecified
urgent
urgent
Target Milestone: rc
: 7.4
Assignee: Ken Gaillot
QA Contact: Asaf Hirshberg
URL:
Whiteboard:
Depends On:
Blocks: 1452196
TreeView+ depends on / blocked
 
Reported: 2017-05-16 02:31 UTC by Andrew Beekhof
Modified: 2020-12-14 08:40 UTC (History)
12 users (show)

Fixed In Version: pacemaker-1.1.16-10.el7
Doc Type: Bug Fix
Doc Text:
Cause: When cancelling a systemd operation, Pacemaker was unable to detect whether it was in-flight. Consequence: If the operation were in-flight, Pacemaker would free its memory, and lrmd would core-dump with a segmentation fault. Fix: Pacemaker can now detect in-flight systemd operations properly. Result: Lrmd does not crash when cancelling an in-flight systemd operation.
Clone Of:
: 1452196 (view as bug list)
Environment:
Last Closed: 2017-08-01 17:57:08 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Cluster Labs 5311 0 None None None 2017-05-16 14:43:02 UTC
Red Hat Product Errata RHEA-2017:1862 0 normal SHIPPED_LIVE pacemaker bug fix and enhancement update 2017-08-01 18:04:15 UTC

Description Andrew Beekhof 2017-05-16 02:31:59 UTC 
Description of problem:

Crash in lrmd leading to implicit action failure.
Core file and logs available on collab-shell: /cases/01819909/sosreport-20170511-115020/ocd00-controller-0.localdomain/sos_commands/pacemaker/crm_report/ocd00-controller-0.localdomain

Version-Release number of selected component (if applicable):

pacemaker 1.1.15-11.el7_3.4 - Red Hat x86_64

How reproducible:

Customer seems to hit it quite regularly

Steps to Reproduce:
1.
2.
3.

Actual results:

Crash and lost action

Expected results:

Prevent crash and perhaps assume that un-ack'd actions were not delivered and should be retried rather than failed.

Additional info:

May 11 10:59:02 ocd00-controller-0 kernel: lrmd[3762]: segfault at 2 ip 00007f165d1ee961 sp 00007ffcf23e27f8 error 4 in libc-2.17.so[7f165d0b3000+1b6000]
May 11 10:59:02 ocd00-controller-0 crmd[3765]:  notice: Result of stop operation for openstack-gnocchi-statsd on ocd00-controller-0: 0 (ok)
May 11 10:59:02 ocd00-controller-0 crmd[3765]:  notice: Initiating stop operation openstack-gnocchi-metricd_stop_0 locally on ocd00-controller-0
May 11 10:59:02 ocd00-controller-0 pacemakerd[3715]:   error: Managed process 3762 (lrmd) dumped core
May 11 10:59:02 ocd00-controller-0 pacemakerd[3715]:   error: The lrmd process (3762) terminated with signal 11 (core=1)
May 11 10:59:02 ocd00-controller-0 pacemakerd[3715]:  notice: Respawning failed child process: lrmd
May 11 10:59:03 ocd00-controller-0 crmd[3765]:   error: Server disconnected client lrmd while waiting for msg id 3901
May 11 10:59:03 ocd00-controller-0 crmd[3765]:  notice: Connection to lrmd closed: Transport endpoint is not connected (-107)
May 11 10:59:03 ocd00-controller-0 crmd[3765]:   error: Couldn't perform lrmd_rsc_cancel operation (timeout=0): -107: Transport endpoint is not connected (107)
May 11 10:59:03 ocd00-controller-0 crmd[3765]:   error: LRMD disconnected
May 11 10:59:03 ocd00-controller-0 crmd[3765]:   error: Operation stop on openstack-gnocchi-metricd failed: -107



[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `/usr/libexec/pacemaker/lrmd'.
Program terminated with signal 11, Segmentation fault.
#0  __strcasecmp_l_avx () at ../sysdeps/x86_64/multiarch/strcmp-sse42.S:164
164		movdqu	(%rdi), %xmm1
Missing separate debuginfos, use: debuginfo-install audit-libs-2.6.5-3.el7.x86_64 gmp-6.0.0-12.el7_1.x86_64 keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.14.1-26.el7.x86_64 libcap-ng-0.7.5-4.el7.x86_64 libcom_err-1.42.9-9.el7.x86_64 libffi-3.0.13-18.el7.x86_64 libselinux-2.5-6.el7.x86_64 libtasn1-3.8-3.el7.x86_64 nettle-2.7.1-8.el7.x86_64 openssl-libs-1.0.1e-60.el7.x86_64 p11-kit-0.20.7-3.el7.x86_64 pcre-8.32-15.el7_2.1.x86_64 trousers-0.3.13-1.el7.x86_64 xz-libs-5.2.2-1.el7.x86_64 zlib-1.2.7-17.el7.x86_64
(gdb) where
#0  __strcasecmp_l_avx () at ../sysdeps/x86_64/multiarch/strcmp-sse42.S:164
#1  0x00007f165f17f44c in crm_str_eq (a=<optimized out>, b=b@entry=0x7f165ffb0a80 "openstack-sahara-api", use_case=use_case@entry=0) at utils.c:1456
#2  0x00007f165ef57b5a in is_op_blocked (rsc=0x7f165ffb0a80 "openstack-sahara-api") at services.c:653
#3  0x00007f165ef57d35 in handle_blocked_ops () at services.c:680
#4  0x00007f165ef58d92 in operation_finalize (op=0x7f165ffdccb0) at services_linux.c:264
#5  0x00007f165ef5bc96 in pcmk_dbus_lookup_result (reply=reply@entry=0x7f165ffcf090, data=data@entry=0x7f165ffbcab0) at dbus.c:289
#6  0x00007f165ef5be44 in pcmk_dbus_lookup_cb (pending=<optimized out>, user_data=0x7f165ffbcab0) at dbus.c:334
#7  0x00007f165eb08862 in complete_pending_call_and_unlock (connection=connection@entry=0x7f165ffb2310, pending=0x7f165ffecbb0, message=message@entry=0x7f165ffcf090) at dbus-connection.c:2314
#8  0x00007f165eb0bb51 in dbus_connection_dispatch (connection=connection@entry=0x7f165ffb2310) at dbus-connection.c:4580
#9  0x00007f165ef5b148 in pcmk_dbus_connection_dispatch (connection=connection@entry=0x7f165ffb2310, new_status=new_status@entry=DBUS_DISPATCH_DATA_REMAINS, data=data@entry=0x0) at dbus.c:410
#10 0x00007f165eb0a260 in _dbus_connection_update_dispatch_status_and_unlock (connection=0x7f165ffb2310, new_status=DBUS_DISPATCH_DATA_REMAINS) at dbus-connection.c:4300
#11 0x00007f165eb0a386 in _dbus_connection_handle_watch (watch=<optimized out>, condition=1, data=0x7f165ffb2310) at dbus-connection.c:1527
#12 0x00007f165eb2262a in dbus_watch_handle (watch=watch@entry=0x7f165ffadcf0, flags=flags@entry=1) at dbus-watch.c:700
#13 0x00007f165ef5ac12 in pcmk_dbus_watch_dispatch (userdata=0x7f165ffadcf0) at dbus.c:448
#14 0x00007f165f19e0c7 in mainloop_gio_callback (gio=<optimized out>, condition=G_IO_IN, data=0x7f165ffb2b90) at mainloop.c:673
#15 0x00007f165c5a5d7a in g_main_dispatch (context=0x7f165ffab140) at gmain.c:3152
#16 g_main_context_dispatch (context=context@entry=0x7f165ffab140) at gmain.c:3767
#17 0x00007f165c5a60b8 in g_main_context_iterate (context=0x7f165ffab140, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3838
#18 0x00007f165c5a638a in g_main_loop_run (loop=0x7f165ff92a80) at gmain.c:4032
#19 0x00007f165f5e03ad in main (argc=<optimized out>, argv=0x7ffcf23e2ed8) at main.c:476


Use after free?

(gdb) down
#2  0x00007f165ef57b5a in is_op_blocked (rsc=0x7f165ffb0a80 "openstack-sahara-api") at services.c:653
653	        if (safe_str_eq(op->rsc, rsc)) {
(gdb) 
#1  0x00007f165f17f44c in crm_str_eq (a=<optimized out>, b=b@entry=0x7f165ffb0a80 "openstack-sahara-api", use_case=use_case@entry=0) at utils.c:1456
1456	    } else if (strcasecmp(a, b) == 0) {
(gdb) print a
$8 = <optimized out>
(gdb) print b
$9 = 0x7f165ffb0a80 "openstack-sahara-api"
(gdb) up
#2  0x00007f165ef57b5a in is_op_blocked (rsc=0x7f165ffb0a80 "openstack-sahara-api") at services.c:653
653	        if (safe_str_eq(op->rsc, rsc)) {
(gdb) print *op
value has been optimized out
(gdb) up
#3  0x00007f165ef57d35 in handle_blocked_ops () at services.c:680
680	        if (is_op_blocked(op->rsc)) {
(gdb) print *op
$10 = {id = 0x7f165ffe13a0 "openstack-sahara-api_stop_0", rsc = 0x7f165ffb0a80 "openstack-sahara-api", action = 0x7f165ffc23f0 "stop", interval = 0, standard = 0x7f165ffbf020 "systemd", 
  provider = 0x0, agent = 0x7f165ffad600 "openstack-sahara-api", timeout = 200000, params = 0x0, rc = 0, pid = 0, cancel = 0, status = 0, sequence = 1446, expected_rc = 0, synchronous = 0, 
  flags = (unknown: 0), stderr_data = 0x0, stdout_data = 0x0, cb_data = 0x7f165ffd9830, opaque = 0x7f165ffe6860}
(gdb) print gIter->prev
$11 = (GList *) 0x0
(gdb) print gIter->next
$12 = (GList *) 0x0
Comment 2 Andrew Beekhof 2017-05-16 03:08:08 UTC 
Aha!  I knew we'd talked about something like this before:

   https://github.com/beekhof/pacemaker/commit/94a4c58f675d163085a055f59fd6c3a2c9f57c43

Leaving this open in case we need a z-stream.
Comment 3 Ken Gaillot 2017-05-16 14:43:02 UTC 
QA: The issue occurs when an in-flight systemd operation is cancelled, which is an accident of timing. To reproduce it reliably for testing:

1. Configure and start a cluster with at least two nodes.
2. Configure a systemd resource named "bz1451170" with a monitor interval of 5 seconds.
3. Find the PID of the lrmd and attach to it with "gdb /usr/libexec/pacemaker/lrmd $PID"
4. At the gdb prompt, run:
# script
b services_add_inflight_op
commands
        if $_streq(op->rsc,"bz1451170")
                call sleep(5)
                finish
                call sleep(5)
        end
        c
end
c
# script end
5. Freeze systemd with "gdb -p 1" immediately after you see `sleep' from the previous step.
6. Cancel the monitor with "lt-lrmd_test -c cancel -a monitor -r p_haproxy -i 5000"

Before the fix, lrmd will crash; after the fix, it won't.
Comment 10 Ken Gaillot 2017-05-18 16:14:41 UTC 
(In reply to Ken Gaillot from comment #3)
> QA: The issue occurs when an in-flight systemd operation is cancelled, which
> is an accident of timing. To reproduce it reliably for testing:

The procedure in Comment 3 had a couple of errors and a few details left out. Here is a better reproducer:

1. Configure a cluster with at least two nodes.
2. Pick a node to use for testing. On it, install the pacemaker-cts and pacemaker-debuginfo packages, and set "MALLOC_PERTURB_=221" in /etc/sysconfig/pacemaker.
3. Start the cluster, and configure a systemd resource (any service will do, or a dummy service) named "bz1451170" with a monitor interval of 5 seconds. Ban the resource from all nodes but the one chosen for testing.
4. Open three terminal windows to the test node, prepare the commands below, and execute them at the appropriate times:
4a. Find the PID of the lrmd. When ready to proceed, attach to it with "gdb /usr/libexec/pacemaker/lrmd $PID", and copy-and-paste this script at the gdb prompt:
break services_add_inflight_op
commands
        if $_streq(op->rsc,"bz1451170")
                echo *** FREEZE SYSTEMD NOW ***\n
                call sleep(5)
                finish
                echo *** CANCEL MONITOR NOW ***\n
                call sleep(5)
                echo *** CONTINUING ***\n
        end
        continue
end
continue
# script end
4b. In a second window, freeze systemd with "gdb -p 1" immediately after gdb in the first window outputs "FREEZE SYSTEMD NOW".
4c. In a third window, cancel the monitor with "/usr/libexec/pacemaker/lrmd_test -c cancel -a monitor -r bz1451170 -i 5000" immediately after gdb in the first window outputs "CANCEL MONITOR NOW".
4d. If the gdb in the first window shows "script end" and goes back to a prompt, enter "c" at that prompt.
4e. Wait a little while, then unfreeze systemd by entering control-D at the gdb prompt in the second window, to exit gdb.

Before the fix, lrmd will usually dump core. Unfortunately it is still timing-sensitive even with all this. Check the pacemaker detail log for a message like "Managed process ... (lrmd) dumped core" (systemd may respawn lrmd immediately, so there might not be any other noticeable effect). If there is no such message, try disabling and re-enabling the bz1451170 resource, and check again. Usually it will dump core at one of these points. If you want to retry the test, stop and start the cluster on the test node between tests to ensure a clean environment. After the fix, lrmd will never core dump, but you will see a message "Will cancel systemd op bz1451170_status_5000 when in-flight instance completes".
Comment 13 errata-xmlrpc 2017-08-01 17:57:08 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHEA-2017:1862
Note You need to log in before you can comment on or make changes to this bug.