[Pacemaker] pcmk_shutdown: Still waiting for crmd
Erik Schwalbe
erik.schwalbe at canoo.com
Mon Dec 12 18:52:08 EST 2011
Hi sorry for my late answer.
I activate debug mode and this is the output during shutdown the node:
Dec 13 00:45:56 san1 kernel: [ 361.100051] INFO: task clvmd:3291 blocked for more than 120 seconds.
Dec 13 00:45:56 san1 kernel: [ 361.100405] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 13 00:45:56 san1 kernel: [ 361.100758] clvmd D ffff88043e51b170 0 3291 1 0x00000000
Dec 13 00:45:56 san1 kernel: [ 361.100763] ffff88043e51b170 0000000000000082 000000033e1b2118 ffff88000fa157e8
Dec 13 00:45:56 san1 kernel: [ 361.100766] ffff88043d7b0e58 ffff88000fa15780 000000000000f9e0 ffff88042469dfd8
Dec 13 00:45:56 san1 kernel: [ 361.100770] 0000000000015780 0000000000015780 ffff88043d7b0e20 ffff88043d7b1118
Dec 13 00:45:56 san1 kernel: [ 361.100773] Call Trace:
Dec 13 00:45:56 san1 kernel: [ 361.100784] [<ffffffff810482ed>] ? finish_task_switch+0x3a/0xaf
Dec 13 00:45:56 san1 kernel: [ 361.100790] [<ffffffff812fb73d>] ? schedule_timeout+0x2e/0xdd
Dec 13 00:45:56 san1 kernel: [ 361.100797] [<ffffffff810e5d79>] ? virt_to_head_page+0x9/0x2a
Dec 13 00:45:56 san1 kernel: [ 361.100800] [<ffffffff812fb5f4>] ? wait_for_common+0xde/0x15b
Dec 13 00:45:56 san1 kernel: [ 361.100803] [<ffffffff8104a4cc>] ? default_wake_function+0x0/0x9
Dec 13 00:45:56 san1 kernel: [ 361.100818] [<ffffffffa020096c>] ? dlm_new_lockspace+0x783/0x8da [dlm]
Dec 13 00:45:56 san1 kernel: [ 361.100822] [<ffffffff810e81a5>] ? __kmalloc+0x12f/0x141
Dec 13 00:45:56 san1 kernel: [ 361.100829] [<ffffffffa0206c67>] ? device_write+0x420/0x5f2 [dlm]
Dec 13 00:45:56 san1 kernel: [ 361.100834] [<ffffffff810cd128>] ? handle_mm_fault+0x7aa/0x80f
Dec 13 00:45:56 san1 kernel: [ 361.100839] [<ffffffff810ef544>] ? vfs_write+0xa9/0x102
Dec 13 00:45:56 san1 kernel: [ 361.100842] [<ffffffff810ef659>] ? sys_write+0x45/0x6e
Dec 13 00:45:56 san1 kernel: [ 361.100845] [<ffffffff81010b42>] ? system_call_fastpath+0x16/0x1b
Dec 13 00:46:06 san1 lrmd: [2597]: debug: rsc:dlm:1 monitor[12] (pid 4716)
Dec 13 00:46:06 san1 lrmd: [4716]: debug: perform_ra_op: resetting scheduler class to SCHED_OTHER
Dec 13 00:46:06 san1 lrmd: [2597]: info: operation monitor[12] on dlm:1 for client 2600: pid 4716 exited with return code 0
Dec 13 00:46:16 san1 corosync[2571]: [pcmk ] notice: pcmk_shutdown: Still waiting for crmd (pid=2600, seq=6) to terminate...
Dec 13 00:46:16 san1 lrmd: [2597]: debug: rsc:dlm:1 monitor[12] (pid 4724)
Dec 13 00:46:16 san1 lrmd: [4724]: debug: perform_ra_op: resetting scheduler class to SCHED_OTHER
Dec 13 00:46:16 san1 lrmd: [2597]: info: operation monitor[12] on dlm:1 for client 2600: pid 4724 exited with return code 0
Dec 13 00:46:26 san1 lrmd: [2597]: debug: rsc:dlm:1 monitor[12] (pid 4732)
Dec 13 00:46:26 san1 lrmd: [4732]: debug: perform_ra_op: resetting scheduler class to SCHED_OTHER
Dec 13 00:46:26 san1 lrmd: [2597]: info: operation monitor[12] on dlm:1 for client 2600: pid 4732 exited with return code 0
Dec 13 00:46:36 san1 lrmd: [2597]: debug: rsc:dlm:1 monitor[12] (pid 4740)
Dec 13 00:46:36 san1 lrmd: [4740]: debug: perform_ra_op: resetting scheduler class to SCHED_OTHER
Dec 13 00:46:36 san1 lrmd: [2597]: info: operation monitor[12] on dlm:1 for client 2600: pid 4740 exited with return code 0
Dec 13 00:46:46 san1 corosync[2571]: [pcmk ] notice: pcmk_shutdown: Still waiting for crmd (pid=2600, seq=6) to terminate...
Dec 13 00:46:46 san1 lrmd: [2597]: debug: rsc:dlm:1 monitor[12] (pid 4748)
Dec 13 00:46:46 san1 lrmd: [4748]: debug: perform_ra_op: resetting scheduler class to SCHED_OTHER
Dec 13 00:46:46 san1 lrmd: [2597]: info: operation monitor[12] on dlm:1 for client 2600: pid 4748 exited with return code 0
Dec 13 00:46:56 san1 lrmd: [2597]: debug: rsc:dlm:1 monitor[12] (pid 4759)
Dec 13 00:46:56 san1 lrmd: [4759]: debug: perform_ra_op: resetting scheduler class to SCHED_OTHER
Dec 13 00:46:56 san1 lrmd: [2597]: info: operation monitor[12] on dlm:1 for client 2600: pid 4759 exited with return code 0
Dec 13 00:47:06 san1 lrmd: [2597]: debug: rsc:dlm:1 monitor[12] (pid 4767)
Dec 13 00:47:06 san1 lrmd: [4767]: debug: perform_ra_op: resetting scheduler class to SCHED_OTHER
Dec 13 00:47:06 san1 lrmd: [2597]: info: operation monitor[12] on dlm:1 for client 2600: pid 4767 exited with return code 0
Regards,
Erik
----- Ursprüngliche Mail -----
Von: "Andrew Beekhof" <andrew at beekhof.net>
An: "The Pacemaker cluster resource manager" <pacemaker at oss.clusterlabs.org>
Gesendet: Donnerstag, 8. Dezember 2011 04:15:46
Betreff: Re: [Pacemaker] pcmk_shutdown: Still waiting for crmd
On Wed, Dec 7, 2011 at 9:44 PM, Erik Schwalbe <erik.schwalbe at canoo.com> wrote:
> Hi,
>
> I think there is never an attempt to demote it.
> kern.log:
>
> 11:35:58 ubuntu1 kernel: Kernel logging (proc) stopped.
>
> corosync.log:
> 11:35:59 ubuntu1 crmd: [839]: info: crm_signal_dispatch: Invoking handler for signal 15: Terminated
> 11:35:59 ubuntu1 crmd: [839]: info: crm_shutdown: Requesting shutdown
> 11:35:59 ubuntu1 crmd: [839]: notice: crm_shutdown: Forcing shutdown in: 1200000ms
>
> after that, there is no entry in kern.log
Sounds strange.
Can you file a bug and attach a crm_report dating from the time you
initiated shutdown please?
>
> Regards,
> Erik
>
>
> ----- Ursprüngliche Mail -----
> Von: "Andreas Kurz" <andreas at hastexo.com>
> An: pacemaker at oss.clusterlabs.org
> Gesendet: Mittwoch, 7. Dezember 2011 11:06:14
> Betreff: Re: [Pacemaker] pcmk_shutdown: Still waiting for crmd
>
> On 12/07/2011 10:27 AM, Erik Schwalbe wrote:
>> Hi,
>>
>> I built a test cluster with 2 nodes.
>> Ubuntu 10.4.3 LTS with *ppa:ubuntu-ha-maintainers/ppa*
>>
>> corosync 1.4.2
>> pacemaker 1.1.6
>>
>> primitive clvm ocf:lvm2:clvmd \
>> params daemon_timeout="30" \
>> operations $id="clvm-operations" \
>> op start interval="0" timeout="90" \
>> op stop interval="0" timeout="100" \
>> op monitor interval="0" timeout="20" start-delay="0" \
>> meta target-role="started"
>> primitive data ocf:heartbeat:LVM \
>> params volgrpname="data" \
>> operations $id="data-operations" \
>> op start interval="0" timeout="30" \
>> op stop interval="0" timeout="30" \
>> op monitor interval="10" timeout="120" start-delay="0" \
>> op methods interval="0" timeout="5" \
>> meta target-role="started"
>> primitive dlm ocf:pacemaker:controld \
>> operations $id="dlm-operations" \
>> op start interval="0" timeout="90" \
>> op stop interval="0" timeout="100" \
>> op monitor interval="10" timeout="20" start-delay="0" \
>> meta target-role="started"
>> primitive fs ocf:heartbeat:Filesystem \
>> params device="/dev/data/test" directory="/data/test"
>> fstype="ocfs2" \
>> operations $id="fs-operations" \
>> op start interval="0" timeout="60" \
>> op stop interval="0" timeout="60" \
>> op monitor interval="120" timeout="40" start-delay="0" \
>> op notify interval="0" timeout="60" \
>> meta target-role="started"
>> primitive o2cb ocf:pacemaker:o2cb \
>> operations $id="o2cb-operations" \
>> op start interval="0" timeout="90" \
>> op stop interval="0" timeout="100" \
>> op monitor interval="0" timeout="20" start-delay="0" \
>> meta target-role="started"
>> primitive res_DRBD ocf:linbit:drbd \
>> params drbd_resource="r0" \
>> operations $id="res_DRBD-operations" \
>> op start interval="0" timeout="240" \
>> op promote interval="0" timeout="90" \
>> op demote interval="0" timeout="90" \
>> op stop interval="0" timeout="100" \
>> op monitor interval="30" timeout="20" start-delay="1min" \
>> op notify interval="0" timeout="90" \
>> meta target-role="started"
>> group dlm-clvm dlm clvm
>> ms ms_DRBD res_DRBD \
>> meta master-max="2" clone-max="2" notify="true" interleave="true"
>> clone clone_data data \
>> meta clone-max="2" ordered="true" interleave="true"
>> clone dlm-clvm-clone dlm-clvm \
>> meta interleave="true" ordered="true"
>> clone fs-clone fs \
>> meta clone-max="2" ordered="true" interleave="true"
>> clone o2cb-clone o2cb \
>> meta clone-max="2" interleave="true"
>> colocation col_data_clvm-dlm-clone inf: clone_data dlm-clvm-clone
>> colocation col_fs_o2cb inf: fs-clone o2cb-clone
>> colocation col_ms_DRBD_dlm-clvm-clone inf: dlm-clvm-clone ms_DRBD:Master
>> colocation col_o2cb_dlm-clvm inf: o2cb-clone dlm-clvm-clone
>> order ord_data_after_clvm-dlm-clone inf: dlm-clvm-clone clone_data
>> order ord_ms_DRBD_dlm-clvm-clone inf: ms_DRBD:promote dlm-clvm-clone:start
>> order ord_o2cb_after_dlm-clvm 0: dlm-clvm-clone o2cb-clone
>> order ord_o2cb_fs inf: o2cb-clone fs-clone
>> property $id="cib-bootstrap-options" \
>> dc-version="1.1.6-9971ebba4494012a93c03b40a2c58ec0eb60f50c" \
>> cluster-infrastructure="openais" \
>> expected-quorum-votes="2" \
>> stonith-enabled="false" \
>> no-quorum-policy="ignore" \
>> last-lrm-refresh="1323246238" \
>> default-resource-stickiness="1000"
>>
>> The problem is to restart corosync or to reboot a cluster node. All
>> resources are stopped except for drbd resource. Than the system hangs
>> for a long time.
>
> Is there a timeout on stopping/demoteing DRBD and do you see kernel
> messages from DRBD about being unable to demote because in use ... or is
> there never an attempt to demote it?
>
> Regards,
> Andreas
>
> --
> Need help with Pacemaker?
> http://www.hastexo.com/now
>
>> corosync.log:
>>
>> ubuntu0 crmd: [926]: info: do_state_transition: (Re)Issuing shutdown
>> request now that we are the DC
>> ubuntu0 crmd: [926]: info: do_state_transition: Starting PEngine Recheck
>> Timer
>> ubuntu0 crmd: [926]: info: do_shutdown_req: Sending shutdown request to
>> DC: ubuntu0
>> ubuntu0 crmd: [926]: info: handle_shutdown_request: Creating shutdown
>> request for ubuntu0 (state=S_IDLE)
>> corosync [pcmk ] notice: pcmk_shutdown: Still waiting for crmd
>> (pid=926, seq=6) to terminate...
>> corosync [pcmk ] notice: pcmk_shutdown: Still waiting for crmd
>> (pid=926, seq=6) to terminate...
>> corosync [pcmk ] notice: pcmk_shutdown: Still waiting for crmd
>> (pid=926, seq=6) to terminate...
>> corosync [pcmk ] notice: pcmk_shutdown: Still waiting for crmd
>> (pid=926, seq=6) to terminate...
>> corosync [pcmk ] notice: pcmk_shutdown: Still waiting for crmd
>> (pid=926, seq=6) to terminate...
>>
>> I tested the same config with a debian 6.0.3. The reboot works. The
>> behaviour there is, that in the first step the drbd resource demote to
>> secondary and then goes down.
>>
>> Is this a known problem??
>>
>> Thank you for help.
>>
>> Regards,
>> Erik
>>
>>
>>
>>
>> _______________________________________________
>> 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
>
> _______________________________________________
> 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
More information about the Pacemaker
mailing list