ClusterLabs / ClusterLabs/resource-agents

Function ha_clustermsg() is not 'statement' safe (packets can be mixed in $HA_FIFO )

Open
#396 5 comments 0 reactions 0 assignees View on GitHub
Dominant language
Shell
Stars
519
Forks
608
Avg merge
6d 1h
Merged PRs (30d)
7

Description

Hi,

Our HA stops working (commonly during the system start) with the error:

```
Feb 6 15:56:15 sp1 heartbeat: [8910]: WARN: ha_msg_add_nv_depth: line doesn't contain '='
Feb 6 15:56:15 sp1 heartbeat: [8910]: info: >>>
Feb 6 15:56:15 sp1 heartbeat: [8910]: ERROR: NV failure (msgfromsteam): [>>>#012]
```

Google shows a lot of such error reports, but no common solution and explanation about the reason. With debug 255 we have the following HA log:

```
...
harc[3112]: 2014/03/16_23:38:30 info: Running /etc/ha.d/rc.d/status status
heartbeat[3113]: 2014/03/16_23:38:30 debug: req_our_resources(): running [/usr/share/heartbeat/req_resource redis-master]
mach_down[3149]: 2014/03/16_23:38:31 info: /usr/share/heartbeat/mach_down: nice_failback: foreign resources acquired
req_resource[3148]: 2014/03/16_23:38:31 debug: in /usr/share/heartbeat/req_resource redis-master
req_resource[3148]: 2014/03/16_23:38:31 debug: dont_ask: yes nice_failback: yes
heartbeat[2194]: 2014/03/16_23:38:31 WARN: ha_msg_add_nv_depth: line doesn't contain '='
heartbeat[2194]: 2014/03/16_23:38:31 info: >>>

heartbeat[2194]: 2014/03/16_23:38:31 ERROR: NV failure (msgfromsteam): [>>>
]
heartbeat[3113]: 2014/03/16_23:38:31 debug: req_our_resources() before fgets()
heartbeat[3113]: 2014/03/16_23:38:31 debug: req_our_resources() fgets => NULL
heartbeat[3113]: 2014/03/16_23:38:31 info: 1 local resources from [/usr/share/heartbeat/ResourceManager listkeys sp1]
heartbeat[3113]: 2014/03/16_23:38:31 info: Local Resource acquisition completed.
heartbeat[3113]: 2014/03/16_23:38:31 debug: Sending hold resources msg: all, stable=1 # req_our_resources()
heartbeat[3113]: 2014/03/16_23:38:31 info: Writing type [resource] message to FIFO
heartbeat[3113]: 2014/03/16_23:38:31 info: FIFO message [type resource] written rc=79
heartbeat[2194]: 2014/03/16_23:38:31 debug: fifo_child message:
heartbeat[2194]: 2014/03/16_23:38:31 debug: MSG: Dumping message with 5 fields
heartbeat[2194]: 2014/03/16_23:38:31 debug: MSG[0] : [t=resource]
heartbeat[2194]: 2014/03/16_23:38:31 debug: MSG[1] : [rsc_hold=all]
heartbeat[2194]: 2014/03/16_23:38:31 debug: MSG[2] : [rtype=full]
heartbeat[2194]: 2014/03/16_23:38:31 debug: MSG[3] : [isstable=1]
heartbeat[2180]: 2014/03/16_23:38:31 debug: polled_input_check(): result = 0
heartbeat[2194]: 2014/03/16_23:38:31 debug: MSG[4] : [info=req_our_resources()]
heartbeat[2180]: 2014/03/16_23:38:31 info: Managed req_our_resources process 3113 exited with return code 0.
heartbeat[2180]: 2014/03/16_23:38:31 debug: RscMgmtProc 'req_our_resources' exited code 0
heartbeat[2180]: 2014/03/16_23:38:31 info: AnnounceTakeover(local 1, foreign 0, reason 'req_our_resources' (0))
...
```

As you can see the HA received the ">>> x=y <<<" packets from mach_down and req_resource simultaneously and says ERROR. I suppose that the packets are mixed during writing to named pipe $HA_FIFO in https://github.com/ClusterLabs/resource-agents/blob/master/heartbeat/shellfuncs.in#L33

This can be easily checked:
1) Stop HA on your system
2) open console 1 and start dumping all the packets to log:

```
while true; do cat /var/lib/heartbeat/fifo | while read line; do echo $line >> /tmp/event.log; done; done
```

3) open console 2 and start writing something in a loop using ha_clustermsg(), like:

```
while true ; do HA_NICEFAILBACK=Yes /usr/share/heartbeat/mach_down nice_failback ; done
```

4) open console 3 and start writing something another in a loop using ha_clustermsg(), like

```
while true; do /usr/share/heartbeat/req_resource redis-master ; done
```

5) check /tmp/event.log, you will see:

```
>>>
t=ip-request
ipaddr=redis-master
<<<
>>>
t=resource
rsc_hold=foreign
info=mach_down
<<<
>>>
t=ip-request
ipaddr=redis-master
<<<
>>>
>>>
t=resource
rsc_hold=foreign
info=mach_down
<<<
t=ip-request
ipaddr=redis-master
<<<
>>>
t=ip-request
ipaddr=redis-master
<<<
>>>
t=resource
rsc_hold=foreign
info=mach_down
<<<
```

As you can see there are mixed "<<<" and ">>>" in the middle of the log. So, the part "| cat -" here https://github.com/ClusterLabs/resource-agents/blob/master/heartbeat/shellfuncs.in#L33 doesn't do the job well.

Sure, we use pretty old HA, but as I can see it is still actual for latest ha_clustermsg() in HA 3. I am not sure that it is the proper place for such bugreport, please point me to proper place if so. Tnx!

P.S. we are using HA 2.1.3 on Debian “wheezy” 3.2.0-4-amd64.

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.