Date: Mon, 17 Jan 2011 10:32:56 +0100 From: Andrew Beekhof <andrew@beekhof.net> To: General Linux-HA mailing list <linux-ha@lists.linux-ha.org> Cc: freebsd-questions <freebsd-questions@freebsd.org> Subject: Re: [Linux-HA] Issues when running Heartbeat on FreeBSD 8.1 RELEASE Message-ID: <AANLkTinfa0xyzjMcjQEfy_jVbg30u2mnOmkR%2B9FFXWAx@mail.gmail.com> In-Reply-To: <1294039617.42493.1291994766801.JavaMail.root@mrelmx10.mrec.ar> References: <1416738542.42422.1291994310297.JavaMail.root@mrelmx10.mrec.ar> <1294039617.42493.1291994766801.JavaMail.root@mrelmx10.mrec.ar>
next in thread | previous in thread | raw e-mail | index | archive | help
On Fri, Dec 10, 2010 at 4:26 PM, Kevin Mai <kma@mrecic.gov.ar> wrote:
> Hi folks,
>
> I'm trying to build a failover solution using FreeBSD 8.1-RELEASE and Hea=
rtbeat from ports (v2.1.4-10).
>
> I've already configured heartbeat in the two peers, but once I start the =
daemon using the /usr/local/etc/rc.d/heartbeat script, either CRM and CIB f=
ail to start.
>
> I've already found out that the issue is appearing with CIB: when the dae=
mon runs CIB it doesn't start, but if I run it using some flags, it starts,=
and them I'm able to run CRM too.
Does uid 275 and gid 275 exist?
Possibly you have some permission issues that go away when you run the
daemons manually (since you're now running them as root).
>
> IE:
> heartbeat[12539]: 2010/12/10_14:22:14 info: Starting "/usr/local/lib/hear=
tbeat/cib" as uid 275 gid 275 (pid 12539)
> heartbeat[12540]: 2010/12/10_14:22:14 info: Starting "/usr/local/lib/hear=
tbeat/attrd" as uid 275 gid 275 (pid 12540)
> heartbeat[12482]: 2010/12/10_14:22:14 WARN: Managed /usr/local/lib/heartb=
eat/cib process 12539 exited with return code 2.
> heartbeat[12482]: 2010/12/10_14:22:14 ERROR: Client /usr/local/lib/heartb=
eat/cib "respawning too fast"
> heartbeat[12541]: 2010/12/10_14:22:14 info: Starting "/usr/local/lib/hear=
tbeat/crmd" as uid 275 gid 275 (pid 12541)
> heartbeat[12482]: 2010/12/10_14:22:14 WARN: Managed /usr/local/lib/heartb=
eat/attrd process 12540 exited with return code 2.
> heartbeat[12482]: 2010/12/10_14:22:14 ERROR: Client /usr/local/lib/heartb=
eat/attrd "respawning too fast"
> heartbeat[12482]: 2010/12/10_14:22:14 WARN: Managed /usr/local/lib/heartb=
eat/crmd process 12541 exited with return code 2.
> heartbeat[12482]: 2010/12/10_14:22:14 ERROR: Client /usr/local/lib/heartb=
eat/crmd "respawning too fast"
>
> but if I run it from command line
>
> [root@mrefns09 /usr/ports]# /usr/local/lib/heartbeat/cib -s -VVV &
> cib[13338]: 2010/12/10_14:30:49 info: main: Retrieval of a per-action CIB=
: disabled
> cib[13338]: 2010/12/10_14:30:49 info: retrieveCib: Reading cluster config=
uration from: /var/lib/heartbeat/crm/cib.xml (digest: /var/lib/heartbeat/cr=
m/cib.xml.sig)
> cib[13338]: 2010/12/10_14:30:49 debug: debug3: file2xml: Reading 3538 byt=
es from file
> cib[13338]: 2010/12/10_14:30:49 WARN: validate_cib_digest: No on-disk dig=
est present
> cib[13338]: 2010/12/10_14:30:49 debug: update_quorum: CCM quorum: old=3D(=
null), new=3Dfalse
> cib[13338]: 2010/12/10_14:30:49 debug: update_counters: Counters updated =
by readCibXmlFile
> cib[13338]: 2010/12/10_14:30:49 notice: readCibXmlFile: Enabling DTD vali=
dation on the existing (sane) configuration
> cib[13338]: 2010/12/10_14:30:49 info: startCib: CIB Initialization comple=
ted successfully
> cib[13338]: 2010/12/10_14:30:49 debug: debug3: init_server_ipc_comms: Lis=
tening on: /var/run/heartbeat/crm/cib_callback
> cib[13338]: 2010/12/10_14:30:49 debug: debug3: init_server_ipc_comms: Lis=
tening on: /var/run/heartbeat/crm/cib_ro
> cib[13338]: 2010/12/10_14:30:49 debug: debug3: init_server_ipc_comms: Lis=
tening on: /var/run/heartbeat/crm/cib_rw
> cib[13338]: 2010/12/10_14:30:49 debug: debug3: init_server_ipc_comms: Lis=
tening on: /var/run/heartbeat/crm/cib_rw_syncronous
> cib[13338]: 2010/12/10_14:30:49 debug: debug3: init_server_ipc_comms: Lis=
tening on: /var/run/heartbeat/crm/cib_ro_syncronous
> cib[13338]: 2010/12/10_14:30:49 info: cib_init: Starting cib mainloop
>
> [root@mrefns09 /usr/local/lib/heartbeat]# /usr/local/lib/heartbeat/crmd -=
VVV
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: main: Enabling coredumps
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: digraph "g" {
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: size =3D "30,30"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: graph [
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: fontsize =3D "12"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: fontname =3D "Times-Roman"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: fontcolor =3D "black"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: bb =3D "0,0,398.922306,478.927856"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: color =3D "black"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: ]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: node [
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: fontsize =3D "12"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: fontname =3D "Times-Roman"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: fontcolor =3D "black"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: shape =3D "ellipse"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: color =3D "black"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: ]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: edge [
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: fontsize =3D "12"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: fontname =3D "Times-Roman"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: fontcolor =3D "black"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: color =3D "black"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: ]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: // special nodes
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: "S_PENDING"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: [
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: color =3D "blue"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: fontcolor =3D "blue"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: ]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: "S_TERMINATE"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: [
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: color =3D "red"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: fontcolor =3D "red"
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: ]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: // DC only nodes
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: "S_INTEGRATION" [ fontcolor =3D "green" ]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: "S_POLICY_ENGINE" [ fontcolor =3D "green" ]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: "S_TRANSITION_ENGINE" [ fontcolor =3D "green" ]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: "S_RELEASE_DC" [ fontcolor =3D "green" ]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: init_dotfile: actions:tra=
ce: "S_IDLE" [ fontcolor =3D "green" ]
> crmd[14877]: 2010/12/10_15:14:28 info: crmd_init: Starting crmd
> crmd[14877]: 2010/12/10_15:14:28 debug: register_fsa_input_adv: crmd_init=
appended FSA input 1 (I_STARTUP) (cause=3DC_STARTUP) without data
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: register_fsa_input_adv: Q=
ueue len: 1
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: s_crmd_fsa: FSA invoked w=
ith Cause: C_STARTUP State: S_STARTING
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: s_crmd_fsa: Checking mess=
ages (1 remaining)
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: get_message: Processing i=
nput 1
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: log_fsa_input: Processing=
queued input 1
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: log_fsa_input: FSA proces=
sing input from crmd_init
> crmd[14877]: 2010/12/10_15:14:28 debug: s_crmd_fsa: Processing I_STARTUP:=
[ state=3DS_STARTING cause=3DC_STARTUP origin=3Dcrmd_init ]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Invoking a=
ction A_LOG (1000000000000000)
> crmd[14877]: 2010/12/10_15:14:28 debug: do_fsa_action: actions:trace: // =
A_LOG
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: do_log: [[FSA]] Input I_S=
TARTUP from crmd_init() received in state (S_STARTING)
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Action com=
plete: A_LOG (1000000000000000)
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: s_crmd_fsa: actions:trace=
: // FSA input: State=3DS_STARTING Cause=3DC_STARTUP Input=3DI_STARTUP Orig=
in=3Dcrmd_init() id=3D1
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Invoking a=
ction A_STARTUP (0000000000000001)
> crmd[14877]: 2010/12/10_15:14:28 debug: do_fsa_action: actions:trace: // =
A_STARTUP
> crmd[14877]: 2010/12/10_15:14:28 debug: do_startup: Registering Signal Ha=
ndlers
> crmd[14877]: 2010/12/10_15:14:28 info: G_main_add_SignalHandler: Added si=
gnal handler for signal 15
> crmd[14877]: 2010/12/10_15:14:28 info: G_main_add_TriggerHandler: Added s=
ignal manual handler
> crmd[14877]: 2010/12/10_15:14:28 debug: do_startup: Creating CIB and LRM =
objects
> crmd[14877]: 2010/12/10_15:14:28 info: G_main_add_SignalHandler: Added si=
gnal handler for signal 20
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Action com=
plete: A_STARTUP (0000000000000001)
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Invoking a=
ction A_CIB_START (0000020000000000)
> crmd[14877]: 2010/12/10_15:14:28 debug: do_fsa_action: actions:trace: // =
A_CIB_START
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: init_client_ipc_comms_nod=
ispatch: Attempting to talk on: /var/run/heartbeat/crm/cib_rw
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: init_client_ipc_comms_nod=
ispatch: Processing of /var/run/heartbeat/crm/cib_rw complete
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: init_client_ipc_comms_nod=
ispatch: Attempting to talk on: /var/run/heartbeat/crm/cib_callback
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: init_client_ipc_comms_nod=
ispatch: Processing of /var/run/heartbeat/crm/cib_callback complete
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: init_client_ipc_comms: Ad=
ding dispatch method to channel
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: cib_client_connect_common:=
Connecting channel
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: cib_client_connect_common:=
Created channel 0x802841958 for channel cib_rw
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: cib_client_connect_common:=
Channel cib_rw connected for client (null)
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: crm_log_message_adv: #=3D=
=3D=3D=3D=3D=3D=3D=3D=3D IPC[outbound] message start =3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D#
> cib[14871]: 2010/12/10_15:14:28 debug: MSG: Dumping message with 3 fields
> cib[14871]: 2010/12/10_15:14:28 debug: MSG[0] : [cib_op=3Dregister]
> cib[14871]: 2010/12/10_15:14:28 debug: MSG[1] : [cib_clientid=3D4821470c-=
0aac-4bd6-9d5b-f4a15fdd063c]
> cib[14871]: 2010/12/10_15:14:28 debug: MSG[2] : [cib_callback_token=3De87=
ceee6-3043-4c2d-b183-b3adeca43683]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: crm_log_message_adv: #=3D=
=3D=3D=3D=3D=3D=3D=3D=3D IPC[outbound] message start =3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D#
> cib[14871]: 2010/12/10_15:14:28 crmd[14877]: 2010/12/10_15:14:28 debug: d=
ebug3: cib_client_connect_common: Connecting channel
> debug: MSG: Dumping message with 3 fields
> crmd[14877]: 2010/12/10_15:14:28 debug: MSG[0] : [cib_op=3Dregister]
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: cib_client_connect_common:=
Created channel 0x802841dd8 for channel cib_callback
> crmd[14877]: 2010/12/10_15:14:28 debug: MSG[1] : [cib_callback_token=3De8=
7ceee6-3043-4c2d-b183-b3adeca43683]
> crmd[14877]: 2010/12/10_15:14:28 debug: MSG[2] : [cib_clientname=3Dcrmd]
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: cib_client_connect_common:=
Channel cib_callback connected for client (null)
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_null_callback: Registe=
red e87ceee6-3043-4c2d-b183-b3adeca43683 on cib_callback channel
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: crm_log_message_adv: #=3D=
=3D=3D=3D=3D=3D=3D=3D=3D IPC[outbound] message start =3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D#
> cib[14871]: 2010/12/10_15:14:28 debug: MSG: Dumping message with 2 fields
> crmd[14877]: 2010/12/10_15:14:28 debug: cib_native_signon: Connection to =
CIB successful
> cib[14871]: 2010/12/10_15:14:28 debug: MSG[0] : [cib_op=3Dregister]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: cib_native_set_connection=
_dnotify: Setting dnotify
> cib[14871]: 2010/12/10_15:14:28 debug: MSG[1] : [cib_clientid=3De87ceee6-=
3043-4c2d-b183-b3adeca43683]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: cib_client_add_notify_cal=
lback: Adding callback for cib_refresh_notify events (0)
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: crm_log_message_adv: #=3D=
=3D=3D=3D=3D=3D=3D=3D=3D IPC[outbound] message start =3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D#
> crmd[14877]: 2010/12/10_15:14:28 debug: MSG: Dumping message with 3 field=
s
> crmd[14877]: 2010/12/10_15:14:28 debug: MSG[0] : [cib_op=3Dcib_notify]
> cib[14871]: 2010/12/10_15:14:28 crmd[14877]: 2010/12/10_15:14:28 info: ci=
b_null_callback: Setting cib_refresh_notify callbacks for crmd: on
> debug: MSG[1] : [cib_notify_type=3Dcib_refresh_notify]
> crmd[14877]: 2010/12/10_15:14:28 debug: MSG[2] : [cib_notify_activate=3D1=
]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: cib_client_add_notify_cal=
lback: Callback added (1)
> crmd[14877]: 2010/12/10_15:14:28 info: do_cib_control: CIB connection est=
ablished
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: cib_native_perform_op: Se=
nding cib_query message to CIB service
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: crm_log_message_adv: #=3D=
=3D=3D=3D=3D=3D=3D=3D=3D IPC[outbound] message start =3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D#
> crmd[14877]: 2010/12/10_15:14:28 debug: MSG: Dumping message with 5 field=
s
> crmd[14877]: 2010/12/10_15:14:28 debug: MSG[0] : [__name__=3Dcib_command]
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_common_callback: Callb=
ack for 4821470c-0aac-4bd6-9d5b-f4a15fdd063c on cib_rw channel
> crmd[14877]: 2010/12/10_15:14:28 debug: MSG[1] : [t=3Dcib]
> crmd[14877]: 2010/12/10_15:14:28 debug: MSG[2] : [cib_op=3Dcib_query]
> cib[14871]: 2010/12/10_15:14:28 crmd[14877]: 2010/12/10_15:14:28 debug: d=
ebug3: crm_log_message_adv: #=3D=3D=3D=3D=3D=3D=3D=3D=3D Client[inbound] me=
ssage start =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D#
> debug: MSG[3] : [cib_callid=3D2]
> cib[14871]: 2010/12/10_15:14:28 crmd[14877]: 2010/12/10_15:14:28 debug: M=
SG: Dumping message with 5 fields
> debug: MSG[4] : [cib_callopt=3D256]
> cib[14871]: 2010/12/10_15:14:28 crmd[14877]: 2010/12/10_15:14:28 debug: M=
SG[0] : [__name__=3Dcib_command]
> debug: debug3: cib_native_perform_op: Message sent
> cib[14871]: 2010/12/10_15:14:28 crmd[14877]: 2010/12/10_15:14:28 debug: M=
SG[1] : [t=3Dcib]
> debug: debug3: cib_native_perform_op: Async call, returning
> cib[14871]: 2010/12/10_15:14:28 debug: MSG[2] : [cib_op=3Dcib_query]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Action com=
plete: A_CIB_START (0000020000000000)
> cib[14871]: 2010/12/10_15:14:28 debug: MSG[3] : [cib_callid=3D2]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Invoking a=
ction A_HA_CONNECT (0000000000000004)
> cib[14871]: 2010/12/10_15:14:28 debug: MSG[4] : [cib_callopt=3D256]
> crmd[14877]: 2010/12/10_15:14:28 debug: do_fsa_action: actions:trace: // =
A_HA_CONNECT
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_common_callback_worker=
: Processing cib_query operation from -1/cib_rw
> crmd[14877]: 2010/12/10_15:14:28 cib[14871]: 2010/12/10_15:14:28 debug: r=
egister_with_ha: Signing in with Heartbeat
> debug: debug2: cib_process_request: Processing local message (localhost) =
for master...
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: parse_local_options: Proce=
ssing locally scoped cib_query op from -1
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: cib_process_request: Finis=
hed determining processing actions
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_process_request: Perfo=
rming local processing: op=3Dcib_query origin=3D(null)/4821470c-0aac-4bd6-9=
d5b-f4a15fdd063c,2 (update=3D(null))
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_process_query: Process=
ing "cib_query" event for section=3D<null>
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_process_request: Proce=
ssing complete
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: cib_process_request: proce=
ssing response cases
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: do_local_notify: Performin=
g notification
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: do_local_notify: Sending c=
allback to request originator
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: do_local_notify: Sending a=
n a-sync response to -1
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: send_via_callback_channel:=
Delivering msg 0x802895538 to client e87ceee6-3043-4c2d-b183-b3adeca43683
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: send_via_callback_channel:=
Delivering reply to client e87ceee6-3043-4c2d-b183-b3adeca43683
> crmd[14877]: 2010/12/10_15:14:28 ERROR: register_with_ha: Cannot sign on =
with heartbeat:
> crmd[14877]: 2010/12/10_15:14:28 debug: register_fsa_input_adv: register_=
fsa_error_adv prepended FSA input 2 (I_NULL) (cause=3DC_STARTUP) without da=
ta
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: register_fsa_input_adv: A=
dding actions 0180001000000002 to input
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: register_fsa_input_adv: P=
repending input
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: register_fsa_input_adv: Q=
ueue len: 1
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: register_fsa_input_adv: T=
riggering FSA: register_fsa_input_adv
> crmd[14877]: 2010/12/10_15:14:28 debug: register_fsa_input_adv: do_ha_con=
trol prepended FSA input 3 (I_FAIL) (cause=3DC_FSA_INTERNAL) without data
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: register_fsa_input_adv: P=
repending input
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: register_fsa_input_adv: Q=
ueue len: 2
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: register_fsa_input_adv: T=
riggering FSA: register_fsa_input_adv
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Action com=
plete: A_HA_CONNECT (0000000000000004)
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: s_crmd_fsa: Checking mess=
ages (2 remaining)
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: get_message: Processing i=
nput 3
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: log_fsa_input: Processing=
queued input 3
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: log_fsa_input: FSA proces=
sing input from do_ha_control
> crmd[14877]: 2010/12/10_15:14:28 debug: s_crmd_fsa: Processing I_FAIL: [ =
state=3DS_STARTING cause=3DC_FSA_INTERNAL origin=3Ddo_ha_control ]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Invoking a=
ction A_WARN (4000000000000000)
> crmd[14877]: 2010/12/10_15:14:28 debug: do_fsa_action: actions:trace: // =
A_WARN
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: crm_log_message_adv: #=3D=
=3D=3D=3D=3D=3D=3D=3D=3D IPC[outbound] message start =3D=3D=3D=3D=3D=3D=3D=
=3D=3D=3D#
> crmd[14877]: 2010/12/10_15:14:28 WARN: do_log: [[FSA]] Input I_FAIL from =
do_ha_control() received in state (S_STARTING)
> cib[14871]: 2010/12/10_15:14:28 debug: MSG: Dumping message with 7 fields
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Action com=
plete: A_WARN (4000000000000000)
> cib[14871]: 2010/12/10_15:14:28 debug: MSG[0] : [t=3Dcib]
> cib[14871]: 2010/12/10_15:14:28 crmd[14877]: 2010/12/10_15:14:28 debug: d=
ebug2: do_state_transition: actions:trace: S_STARTING -> S_STOPPING [ label=
=3DI_FAIL cause=3DC_FSA_INTERNAL origin=3Ddo_ha_control ]
> debug: MSG[1] : [cib_clientid=3D4821470c-0aac-4bd6-9d5b-f4a15fdd063c]
> crmd[14877]: 2010/12/10_15:14:28 cib[14871]: 2010/12/10_15:14:28 info: do=
_state_transition: State transition S_STARTING -> S_STOPPING [ input=3DI_FA=
IL cause=3DC_FSA_INTERNAL origin=3Ddo_ha_control ]
> debug: MSG[2] : [cib_callopt=3D256]
> crmd[14877]: 2010/12/10_15:14:28 cib[14871]: 2010/12/10_15:14:28 debug: d=
ebug2: crm_timer_stop: Election Timeout (I_ELECTION_DC:-1ms) already stoppe=
d
> debug: MSG[3] : [cib_callid=3D2]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: crm_timer_stop: PEngine R=
echeck Timer (I_PE_CALC:-1ms) already stopped
> cib[14871]: 2010/12/10_15:14:28 debug: MSG[4] : [cib_op=3Dcib_query]
> crmd[14877]: 2010/12/10_15:14:28 cib[14871]: 2010/12/10_15:14:28 debug: d=
ebug3: fsa_dump_actions: Action 0000000000000200 (A_DC_TIMER_STOP) New acti=
ons
> debug: MSG[5] : [cib_rc=3D0]
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: fsa_dump_actions: Action =
0000000000000020 (A_INTEGRATE_TIMER_STOP) New actions
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: fsa_dump_actions: Action =
0000000000000080 (A_FINALIZE_TIMER_STOP) New actions
> cib[14871]: 2010/12/10_15:14:28 debug: MSG[6] : [(2)cib_calldata=3D0x8028=
a65f8(4108 5133)]
> cib[14871]: 2010/12/10_15:14:28 debug: <cib admin_epoch=3D"0" epoch=3D"0"=
num_updates=3D"0" generated=3D"false" have_quorum=3D"false" ignore_dtd=3D"=
false">
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Invoking a=
ction A_DC_TIMER_STOP (0000000000000200)
> cib[14871]: 2010/12/10_15:14:28 debug: <configuration>
> crmd[14877]: 2010/12/10_15:14:28 cib[14871]: 2010/12/10_15:14:28 debug: d=
o_fsa_action: actions:trace: // A_DC_TIMER_STOP
> debug: <crm_config>
> crmd[14877]: 2010/12/10_15:14:28 cib[14871]: 2010/12/10_15:14:28 debug: d=
ebug2: crm_timer_stop: Election Trigger (I_DC_TIMEOUT:-1ms) already stopped
> debug: <cluster_property_set id=3D"cib-bootstrap-options">
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Action com=
plete: A_DC_TIMER_STOP (0000000000000200)
> cib[14871]: 2010/12/10_15:14:28 debug: <attributes>
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Invoking a=
ction A_INTEGRATE_TIMER_STOP (0000000000000020)
> cib[14871]: 2010/12/10_15:14:28 debug: <nvpair id=3D"cib-bootstrap-option=
s-symmetric-cluster" name=3D"symmetric-cluster" value=3D"true"/>
> crmd[14877]: 2010/12/10_15:14:28 debug: do_fsa_action: actions:trace: // =
A_INTEGRATE_TIMER_STOP
> cib[14871]: 2010/12/10_15:14:28 debug: <nvpair id=3D"cib-bootstrap-option=
s-no-quorum-policy" name=3D"no-quorum-policy" value=3D"stop"/>
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: crm_timer_stop: Integrati=
on Timer (I_INTEGRATED:-1ms) already stopped
> cib[14871]: 2010/12/10_15:14:28 debug: <nvpair id=3D"cib-bootstrap-option=
s-default-resource-stickiness" name=3D"default-resource-stickiness" value=
=3D"0"/>
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Action com=
plete: A_INTEGRATE_TIMER_STOP (0000000000000020)
> cib[14871]: 2010/12/10_15:14:28 debug: <nvpair id=3D"cib-bootstrap-option=
s-default-resource-failure-stickiness" name=3D"default-resource-failure-sti=
ckiness" value=3D"0"/>
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: do_fsa_action: Invoking a=
ction A_FINALIZE_TIMER_STOP (0000000000000080)
> cib[14871]: 2010/12/10_15:14:28 debug: <nvpair id=3D"cib-bootstrap-option=
s-stonith-enabled" name=3D"stonith-enabled" value=3D"false"/>
> crmd[14877]: 2010/12/10_15:14:28 debug: do_fsa_action: actions:trace: // =
A_FINALIZE_TIMER_STOP
> cib[14871]: 2010/12/10_15:14:28 debug: <nvpair id=3D"cib-bootstrap-option=
s-stonith-action" name=3D"stonith-action" value=3D"reboot"/>
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: crm_timer_stop: Finalizat=
ion Timer (I_ELECTION:-1ms) already stopped
> cib[14871]: 2010/12/10_15:14:28 crmd[14877]: 2010/12/10_15:14:28 debug: <=
nvpair id=3D"cib-bootstrap-options-startup-fencing" name=3D"startup-fencing=
" value=3D"true"/>
> debug: debug3: do_fsa_action: Action complete: A_FINALIZE_TIMER_STOP (000=
0000000000080)
> cib[14871]: 2010/12/10_15:14:28 crmd[14877]: 2010/12/10_15:14:28 debug: <=
nvpair id=3D"cib-bootstrap-options-stop-orphan-resources" name=3D"stop-orph=
an-resources" value=3D"true"/>
> debug: debug2: s_crmd_fsa: Checking messages (1 remaining)
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: get_message: Processing i=
nput 2
> cib[14871]: 2010/12/10_15:14:28 debug: <nvpair id=3D"cib-bootstrap-option=
s-stop-orphan-actions" name=3D"stop-orphan-actions" value=3D"true"/>
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: log_fsa_input: Processing=
queued input 2
> cib[14871]: 2010/12/10_15:14:28 debug: <nvpair id=3D"cib-bootstrap-option=
s-remove-after-stop" name=3D"remove-after-stop" value=3D"false"/>
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: log_fsa_input: FSA proces=
sing input from register_fsa_error_adv
> cib[14871]: 2010/12/10_15:14:28 crmd[14877]: 2010/12/10_15:14:28 debug: <=
nvpair id=3D"cib-bootstrap-options-short-resource-names" name=3D"short-reso=
urce-names" value=3D"true"/>
> debug: debug3: fsa_dump_actions: Action 0080000000000000 (A_READCONFIG) C=
leared Actions
> crmd[14877]: 2010/12/10_15:14:28 cib[14871]: 2010/12/10_15:14:28 debug: d=
ebug3: fsa_dump_actions: Action 0000000000000002 (A_STARTED) Cleared Action=
s
> debug: <nvpair id=3D"cib-bootstrap-options-transition-idle-timeout" name=
=3D"transition-idle-timeout" value=3D"5min"/>
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: fsa_dump_actions: Action =
0100000000000000 (A_LRM_CONNECT) Cleared Actions
> cib[14871]: 2010/12/10_15:14:28 debug: <nvpair id=3D"cib-bootstrap-option=
s-default-action-timeout" name=3D"default-action-timeout" value=3D"20s"/>
> crmd[14877]: 2010/12/10_15:14:28 debug: debug3: fsa_dump_actions: Action =
0000001000000000 (A_CCM_CONNECT) Cleared Actions
> cib[14871]: 2010/12/10_15:14:28 debug: <nvpair id=3D"cib-bootstrap-option=
s-is-managed-default" name=3D"is-managed-default" value=3D"true"/>
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: s_crmd_fsa: actions:trace=
: // FSA input: State=3DS_STOPPING Cause=3DC_STARTUP Input=3DI_NULL Origin=
=3Dregister_fsa_error_adv() id=3D2
> cib[14871]: 2010/12/10_15:14:28 debug: <nvpair id=3D"cib-bootstrap-option=
s-cluster-delay" name=3D"cluster-delay" value=3D"60s"/>
> crmd[14877]: 2010/12/10_15:14:28 debug: debug2: s_crmd_fsa: Exiting the F=
SA
> cib[14871]: 2010/12/10_15:14:28 crmd[14877]: 2010/12/10_15:14:28 debug: <=
nvpair id=3D"cib-bootstrap-options-pe-error-series-max" name=3D"pe-error-se=
ries-max" value=3D"-1"/>
> debug: fsa_dump_inputs: Added input: 0000000000000004 (R_SHUTDOWN)
> crmd[14877]: 2010/12/10_15:14:28 cib[14871]: 2010/12/10_15:14:28 debug: <=
nvpair id=3D"cib-bootstrap-options-pe-warn-series-max" name=3D"pe-warn-seri=
es-max" value=3D"-1"/>
> debug: fsa_dump_inputs: Added input: 0000000000000100 (R_CIB_CONNECTED)
> crmd[14877]: 2010/12/10_15:14:28 cib[14871]: 2010/12/10_15:14:28 ERROR: c=
rmd_init: Startup of crmd failed. Current state: S_STOPPING
> debug: <nvpair id=3D"cib-bootstrap-options-pe-input-series-max" name=3D"p=
e-input-series-max" value=3D"-1"/>
> crmd[14877]: 2010/12/10_15:14:28 info: crmd_init: [crmd] stopped (1)
> cib[14871]: 2010/12/10_15:14:28 debug: </attributes>
> cib[14871]: 2010/12/10_15:14:28 debug: </cluster_property_set>
> cib[14871]: 2010/12/10_15:14:28 debug: </crm_config>
> cib[14871]: 2010/12/10_15:14:28 debug: <nodes/>
> cib[14871]: 2010/12/10_15:14:28 debug: <resources>
> cib[14871]: 2010/12/10_15:14:28 debug: <group id=3D"group_1">
> cib[14871]: 2010/12/10_15:14:28 debug: <primitive class=3D"ocf" id=3D"IPa=
ddr_200_16_97_6" provider=3D"heartbeat" type=3D"IPaddr">
> cib[14871]: 2010/12/10_15:14:28 debug: <operations>
> cib[14871]: 2010/12/10_15:14:28 debug: <op id=3D"IPaddr_200_16_97_6_mon" =
interval=3D"5s" name=3D"monitor" timeout=3D"5s"/>
> cib[14871]: 2010/12/10_15:14:28 debug: </operations>
> cib[14871]: 2010/12/10_15:14:28 debug: <instance_attributes id=3D"IPaddr_=
200_16_97_6_inst_attr">
> cib[14871]: 2010/12/10_15:14:28 debug: <attributes>
> cib[14871]: 2010/12/10_15:14:28 debug: <nvpair id=3D"IPaddr_200_16_97_6_a=
ttr_0" name=3D"ip" value=3D"200.16.97.6"/>
> cib[14871]: 2010/12/10_15:14:28 debug: </attributes>
> cib[14871]: 2010/12/10_15:14:28 debug: </instance_attributes>
> cib[14871]: 2010/12/10_15:14:28 debug: </primitive>
> cib[14871]: 2010/12/10_15:14:28 debug: <primitive class=3D"ocf" id=3D"IPa=
ddr_200_16_98_6" provider=3D"heartbeat" type=3D"IPaddr">
> cib[14871]: 2010/12/10_15:14:28 debug: <operations>
> cib[14871]: 2010/12/10_15:14:28 debug: <op id=3D"IPaddr_200_16_98_6_mon" =
interval=3D"5s" name=3D"monitor" timeout=3D"5s"/>
> cib[14871]: 2010/12/10_15:14:28 debug: </operations>
> cib[14871]: 2010/12/10_15:14:28 debug: <instance_attributes id=3D"IPaddr_=
200_16_98_6_inst_attr">
> cib[14871]: 2010/12/10_15:14:28 debug: <attributes>
> cib[14871]: 2010/12/10_15:14:28 debug: <nvpair id=3D"IPaddr_200_16_98_6_a=
ttr_0" name=3D"ip" value=3D"200.16.98.6"/>
> cib[14871]: 2010/12/10_15:14:28 debug: </attributes>
> cib[14871]: 2010/12/10_15:14:28 debug: </instance_attributes>
> cib[14871]: 2010/12/10_15:14:28 debug: </primitive>
> cib[14871]: 2010/12/10_15:14:28 debug: <primitive class=3D"heartbeat" id=
=3D"jail_3" provider=3D"heartbeat" type=3D"jail">
> cib[14871]: 2010/12/10_15:14:28 debug: <operations>
> cib[14871]: 2010/12/10_15:14:28 debug: <op id=3D"jail_3_mon" interval=3D"=
120s" name=3D"monitor" timeout=3D"60s"/>
> cib[14871]: 2010/12/10_15:14:28 debug: </operations>
> cib[14871]: 2010/12/10_15:14:28 debug: </primitive>
> cib[14871]: 2010/12/10_15:14:28 debug: </group>
> cib[14871]: 2010/12/10_15:14:28 debug: </resources>
> cib[14871]: 2010/12/10_15:14:28 debug: <constraints>
> cib[14871]: 2010/12/10_15:14:28 debug: <rsc_location id=3D"rsc_location_g=
roup_1" rsc=3D"group_1">
> cib[14871]: 2010/12/10_15:14:28 debug: <rule id=3D"prefered_location_grou=
p_1" score=3D"100">
> cib[14871]: 2010/12/10_15:14:28 debug: <expression attribute=3D"#uname" i=
d=3D"prefered_location_group_1_expr" operation=3D"eq" value=3D"mrefns09.mre=
c.ar"/>
> cib[14871]: 2010/12/10_15:14:28 debug: </rule>
> cib[14871]: 2010/12/10_15:14:28 debug: </rsc_location>
> cib[14871]: 2010/12/10_15:14:28 debug: </constraints>
> cib[14871]: 2010/12/10_15:14:28 debug: </configuration>
> cib[14871]: 2010/12/10_15:14:28 debug: <status/>
> cib[14871]: 2010/12/10_15:14:28 debug: </cib>
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_process_request: Compl=
eted slave update
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_common_callback: Proce=
ssed 1 messages
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_common_callback: Callb=
ack for 4821470c-0aac-4bd6-9d5b-f4a15fdd063c on cib_rw channel
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_common_callback: Proce=
ssed 0 messages
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_common_callback: Clien=
t disconnected
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_process_disconnect: Cl=
eaning up after client disconnect: -1/cib_rw/4821470c-0aac-4bd6-9d5b-f4a15f=
dd063c
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: cib_ipc_connection_destroy=
: Destroying -1 (0x802841958)
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_ipc_connection_destroy=
: Num unfree'd clients: 1
>
> [root@mrefns09 /usr/local/lib/heartbeat]# cib[14871]: 2010/12/10_15:14:28=
debug: debug2: cib_null_callback: Client disconnected
>
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_process_disconnect: Cl=
eaning up after client disconnect: crmd/cib_callback/e87ceee6-3043-4c2d-b18=
3-b3adeca43683
> cib[14871]: 2010/12/10_15:14:28 debug: debug3: cib_ipc_connection_destroy=
: Destroying crmd (0x802841dd8)
> cib[14871]: 2010/12/10_15:14:28 debug: debug2: cib_ipc_connection_destroy=
: Num unfree'd clients: 0
>
>
> If I'm not mistaken, running as root allos CIB/CRMD to speak through sock=
et, but if they are run through the rc script, they can't, even though the =
socket has
>
> [root@mrefns09 /var/run/heartbeat/crm]# ls -lrtah
> total 4
> srwxrwxrwx 1 hacluster haclient 0B Dec 10 15:13 cib_rw_syncronous
> srwxrwxrwx 1 hacluster haclient 0B Dec 10 15:13 cib_rw
> srwxrwxrwx 1 hacluster haclient 0B Dec 10 15:13 cib_ro_syncronous
> srwxrwxrwx 1 hacluster haclient 0B Dec 10 15:13 cib_ro
> srwxrwxrwx 1 hacluster haclient 0B Dec 10 15:13 cib_callback
> drwxr-x--- 2 hacluster haclient 512B Dec 10 15:13 .
> drwxr-xr-x 6 hacluster haclient 512B Dec 10 15:21 ..
>
> Since both processes are started by the heartbeat binary, it's not an opt=
ion to change the rc script to run both binaries by hand..
>
> Any suggestions?
>
> Kind Regards,
>
> Kevin Mai
>
> Direcci=F3n de Tecnolog=EDas de la Informaci=F3n
> y las Comunicaciones Asociadas
>
> Ministerio de Relaciones Exteriores, Comercio Internacional y Culto
> Esmeralda 1212 Piso 3
> Tel: +54 011 5555-8900 (int. 3077)
>
> _______________________________________________
> Linux-HA mailing list
> Linux-HA@lists.linux-ha.org
> http://lists.linux-ha.org/mailman/listinfo/linux-ha
> See also: http://linux-ha.org/ReportingProblems
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?AANLkTinfa0xyzjMcjQEfy_jVbg30u2mnOmkR%2B9FFXWAx>