unexpected restart of node ?

G

Gerhard W. Recher

Well-Known Member
Mar 10, 2017
158
8
58
Munich
Hi Folks,
I have a strange problem, Fresh install of 4.4 on 4 nodes all NVMe
last morning and today a vm has been stopped automatically and migrated to next node
I can't find errors in logs, how to debug this strange behavior ?
Worst of all vm has a mysql instance as slave after second migration replication stopped due to data corruption :(

Regards
Gerhard
 

Attachments

  • clusterstatus.PNG
    clusterstatus.PNG
    107.3 KB · Views: 19
the only time anything gets moved from one node to another automatically is with HA - do you have HA enabled? did one of your nodes get fenced?
 
Fabian,
yes i enabled ha
but defined no watchdogs ....

node 2 restarted 01:57:xx without any reason i see nothing in syslog or messages ...
only strange thing is after reboot :

Jun 9 04:17:34 pve02 kernel: [ 8398.132770] perf interrupt took too long (2502 > 2500), lowering kernel.perf_event_max_sample_rate to 50000



Jun 9 01:57:54 pve02 kernel: [ 17.597811] softdog: Software Watchdog Timer: 0.08 initialized. soft_noboot=0 soft_margin=60 sec soft_panic=0 (nowayout=0)
Jun 9 01:57:54 pve02 kernel: [ 17.603231] ip_tables: (C) 2000-2006 Netfilter Core Team
Jun 9 01:57:54 pve02 kernel: [ 17.603286] cgroup: new mount options do not match the existing superblock, will be ignored
Jun 9 01:57:54 pve02 kernel: [ 17.610696] Process accounting resumed
Jun 9 01:57:55 pve02 kernel: [ 18.772889] SGI XFS with ACLs, security attributes, realtime, no debug enabled
Jun 9 01:57:55 pve02 kernel: [ 18.775300] XFS (nvme4n1p1): Mounting V4 Filesystem
Jun 9 01:57:55 pve02 kernel: [ 18.794215] XFS (nvme4n1p1): Starting recovery (logdev: internal)
Jun 9 01:57:55 pve02 kernel: [ 18.805327] XFS (nvme4n1p1): Ending recovery (logdev: internal)
Jun 9 01:57:55 pve02 kernel: [ 19.047692] ip6_tables: (C) 2000-2006 Netfilter Core Team
Jun 9 01:57:55 pve02 kernel: [ 19.054713] ip_set: protocol 6
Jun 9 01:57:57 pve02 kernel: [ 20.943020] XFS (nvme1n1p1): Mounting V4 Filesystem
Jun 9 01:57:57 pve02 kernel: [ 20.962306] XFS (nvme1n1p1): Starting recovery (logdev: internal)
Jun 9 01:57:57 pve02 kernel: [ 20.975699] XFS (nvme1n1p1): Ending recovery (logdev: internal)
Jun 9 01:57:57 pve02 kernel: [ 21.352622] XFS (nvme3n1p1): Mounting V4 Filesystem
Jun 9 01:57:57 pve02 kernel: [ 21.373930] XFS (nvme3n1p1): Starting recovery (logdev: internal)
Jun 9 01:57:57 pve02 kernel: [ 21.383888] XFS (nvme3n1p1): Ending recovery (logdev: internal)
Jun 9 01:57:58 pve02 kernel: [ 21.774209] XFS (nvme2n1p1): Mounting V4 Filesystem
Jun 9 01:57:58 pve02 kernel: [ 21.794361] XFS (nvme2n1p1): Starting recovery (logdev: internal)
Jun 9 01:57:58 pve02 kernel: [ 21.802328] XFS (nvme2n1p1): Ending recovery (logdev: internal)
Jun 9 01:57:58 pve02 kernel: [ 22.203502] XFS (nvme5n1p1): Mounting V4 Filesystem
Jun 9 01:57:58 pve02 kernel: [ 22.223648] XFS (nvme5n1p1): Starting recovery (logdev: internal)
Jun 9 01:57:58 pve02 kernel: [ 22.232672] XFS (nvme5n1p1): Ending recovery (logdev: internal)
Jun 9 01:57:59 pve02 kernel: [ 22.625416] XFS (nvme6n1p1): Mounting V4 Filesystem
Jun 9 01:57:59 pve02 kernel: [ 22.642007] XFS (nvme6n1p1): Starting recovery (logdev: internal)
Jun 9 01:57:59 pve02 kernel: [ 22.649833] XFS (nvme6n1p1): Ending recovery (logdev: internal)
Jun 9 01:57:59 pve02 kernel: [ 23.042473] XFS (nvme0n1p1): Mounting V4 Filesystem
Jun 9 01:57:59 pve02 kernel: [ 23.048310] XFS (nvme0n1p1): Starting recovery (logdev: internal)
Jun 9 01:57:59 pve02 kernel: [ 23.052789] XFS (nvme0n1p1): Ending recovery (logdev: internal)
Jun 9 01:58:01 pve02 pve-manager[4601]: <root@pam> starting task UPID:pve02:0000129F:000009AC:5939E489:startall::root@pam:
Jun 9 01:58:01 pve02 pve-manager[4601]: <root@pam> end task UPID:pve02:0000129F:000009AC:5939E489:startall::root@pam: OK
Jun 9 04:17:34 pve02 kernel: [ 8398.132770] perf interrupt took too long (2502 > 2500), lowering kernel.perf_event_max_sample_rate to 50000
Jun 9 06:25:07 pve02 rsyslogd: [origin software="rsyslogd" swVersion="8.4.2" x-pid="1854" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Jun 9 06:27:54 pve02 rsyslogd0: action 'action 17' resumed (module 'builtin:ompipe') [try http://www.rsyslog.com/e/0 ]
Jun 9 06:27:54 pve02 rsyslogd-2359: action 'action 17' resumed (module 'builtin:ompipe') [try http://www.rsyslog.com/e/2359 ]



root@pve02:/etc/pve# cd ha/
root@pve02:/etc/pve/ha# ls -latr
total 2
drwxr-xr-x 2 root www-data 0 Jan 1 1970 ..
-rw-r----- 1 root www-data 71 Jun 7 22:46 groups.cfg
drwxr-xr-x 2 root www-data 0 Jun 7 22:46 .
-rw-r----- 1 root www-data 51 Jun 7 22:47 resources.cfg
-rw-r----- 1 root www-data 236 Jun 9 14:33 manager_status
-rw-r----- 1 root www-data 0 Jun 9 14:33 crm_commands
root@pve02:/etc/pve/ha# cat groups.cfg
group: all
nodes pve04,pve03,pve02,pve01
nofailback 0
restricted 0

root@pve02:/etc/pve/ha# cat resources.cfg
vm: 100
comment dbserv
group all
state started

root@pve02:/etc/pve/ha# cat manager_status
{"master_node":"pve04","node_status":{"pve01":"online","pve02":"online","pve04":"online","pve03":"online"},"timestamp":1497011674,"service_status":{"vm:100":{"state":"started","node":"pve01","uid":"dQScos2TMn6Qj35uB10UzA","running":1}}}
 
PVE uses a software watchdog timer by default. See https://pve.proxmox.com/pve-docs/pve-admin-guide.html#chapter_ha_manager for lots more information, especially https://pve.proxmox.com/pve-docs/pve-admin-guide.html#ha_manager_fencing ..

My guess is your node got fenced (you can check the OTHER nodes' logs to see if the HA master detected it going offline and initialized recovery actions, the self-fencing event sometimes does not get logged on the node itself, e.g. do "journalctl --since "2017-06-09" --until "2017-06-10" -u 'pve-ha-*'" on all three nodes to see all HA logs for that day)
 
Fabian thanks for this advice

I have no glue why this fencing occurs ... clusterlink is 40GbitE Mellanox .... and as far as i can see sx1012 Mellanox switch has no issues ...
just another restart occurred on node1

not all nodes have corresponding entries ... i'm confused ...

root@pve04:~# journalctl --since "2017-06-09" --until "2017-06-10" -u 'pve-ha-*'
-- Logs begin at Thu 2017-06-08 00:23:13 CEST, end at Fri 2017-06-09 15:53:17 CEST. --
Jun 09 01:54:19 pve04 pve-ha-crm[2501]: successfully acquired lock 'ha_manager_lock'
Jun 09 01:54:19 pve04 pve-ha-crm[2501]: watchdog active
Jun 09 01:54:19 pve04 pve-ha-crm[2501]: status change slave => master
Jun 09 01:54:19 pve04 pve-ha-crm[2501]: node 'pve02': state changed from 'online' => 'unknown'
Jun 09 01:55:19 pve04 pve-ha-crm[2501]: service 'vm:100': state changed from 'started' to 'fence'
Jun 09 01:55:19 pve04 pve-ha-crm[2501]: node 'pve02': state changed from 'unknown' => 'fence'
Jun 09 01:55:29 pve04 pve-ha-crm[2501]: successfully acquired lock 'ha_agent_pve02_lock'
Jun 09 01:55:29 pve04 pve-ha-crm[2501]: fencing: acknowledged - got agent lock for node 'pve02'
Jun 09 01:55:29 pve04 pve-ha-crm[2501]: node 'pve02': state changed from 'fence' => 'unknown'
Jun 09 01:55:29 pve04 pve-ha-crm[2501]: recover service 'vm:100' from fenced node 'pve02' to node 'pve01'
Jun 09 01:55:29 pve04 pve-ha-crm[2501]: service 'vm:100': state changed from 'fence' to 'started' (node = pve01)
Jun 09 01:58:09 pve04 pve-ha-crm[2501]: node 'pve02': state changed from 'unknown' => 'online'
Jun 09 05:01:04 pve04 pve-ha-crm[2501]: node 'pve02': state changed from 'online' => 'unknown'
Jun 09 05:04:49 pve04 pve-ha-crm[2501]: node 'pve02': state changed from 'unknown' => 'online'
Jun 09 15:40:17 pve04 pve-ha-crm[2501]: node 'pve01': state changed from 'online' => 'unknown'
Jun 09 15:41:16 pve04 pve-ha-crm[2501]: service 'vm:100': state changed from 'started' to 'fence'
Jun 09 15:41:16 pve04 pve-ha-crm[2501]: node 'pve01': state changed from 'unknown' => 'fence'
Jun 09 15:42:26 pve04 pve-ha-crm[2501]: successfully acquired lock 'ha_agent_pve01_lock'
Jun 09 15:42:26 pve04 pve-ha-crm[2501]: fencing: acknowledged - got agent lock for node 'pve01'
Jun 09 15:42:26 pve04 pve-ha-crm[2501]: node 'pve01': state changed from 'fence' => 'unknown'
Jun 09 15:42:26 pve04 pve-ha-crm[2501]: recover service 'vm:100' from fenced node 'pve01' to node 'pve02'
Jun 09 15:42:26 pve04 pve-ha-crm[2501]: service 'vm:100': state changed from 'fence' to 'started' (node = pve02)
Jun 09 15:45:46 pve04 pve-ha-crm[2501]: node 'pve01': state changed from 'unknown' => 'online'

root@pve01:~# journalctl --since "2017-06-09" --until "2017-06-10" -u 'pve-ha-*'
-- Logs begin at Fri 2017-06-09 15:45:32 CEST, end at Fri 2017-06-09 16:00:05 CEST. --
Jun 09 15:45:40 pve01 systemd[1]: Starting PVE Cluster Ressource Manager Daemon...
Jun 09 15:45:40 pve01 pve-ha-crm[2815]: starting server
Jun 09 15:45:40 pve01 pve-ha-crm[2815]: status change startup => wait_for_quorum
Jun 09 15:45:40 pve01 systemd[1]: Started PVE Cluster Ressource Manager Daemon.
Jun 09 15:45:40 pve01 systemd[1]: Starting PVE Local HA Ressource Manager Daemon...
Jun 09 15:45:40 pve01 pve-ha-lrm[3000]: starting server
Jun 09 15:45:40 pve01 pve-ha-lrm[3000]: status change startup => wait_for_agent_lock
Jun 09 15:45:40 pve01 systemd[1]: Started PVE Local HA Ressource Manager Daemon.
Jun 09 15:45:50 pve01 pve-ha-crm[2815]: status change wait_for_quorum => slave
root@pve01:~#


root@pve02:/etc/pve/ha# journalctl --since "2017-06-09" --until "2017-06-10" -u 'pve-ha-*'
-- Logs begin at Fri 2017-06-09 01:57:49 CEST, end at Fri 2017-06-09 15:58:54 CEST. --
Jun 09 01:57:56 pve02 systemd[1]: Starting PVE Cluster Ressource Manager Daemon...
Jun 09 01:57:56 pve02 pve-ha-crm[2160]: starting server
Jun 09 01:57:56 pve02 pve-ha-crm[2160]: status change startup => wait_for_quorum
Jun 09 01:57:56 pve02 systemd[1]: Started PVE Cluster Ressource Manager Daemon.
Jun 09 01:57:56 pve02 systemd[1]: Starting PVE Local HA Ressource Manager Daemon...
Jun 09 01:57:57 pve02 pve-ha-lrm[2163]: starting server
Jun 09 01:57:57 pve02 pve-ha-lrm[2163]: status change startup => wait_for_agent_lock
Jun 09 01:57:57 pve02 systemd[1]: Started PVE Local HA Ressource Manager Daemon.
Jun 09 01:58:06 pve02 pve-ha-crm[2160]: status change wait_for_quorum => slave
Jun 09 05:00:52 pve02 pve-ha-crm[2160]: status change slave => wait_for_quorum
Jun 09 05:00:52 pve02 pve-ha-lrm[2163]: unable to write lrm status file - closing file '/etc/pve/nodes/pve02/lrm_status.tmp.2163' failed - Operation not permitted
Jun 09 05:04:52 pve02 pve-ha-crm[2160]: status change wait_for_quorum => slave
Jun 09 15:42:33 pve02 pve-ha-lrm[2163]: successfully acquired lock 'ha_agent_pve02_lock'
Jun 09 15:42:33 pve02 pve-ha-lrm[2163]: watchdog active
Jun 09 15:42:33 pve02 pve-ha-lrm[2163]: status change wait_for_agent_lock => active
Jun 09 15:42:33 pve02 pve-ha-lrm[16967]: starting service vm:100
Jun 09 15:42:33 pve02 pve-ha-lrm[16967]: <root@pam> starting task UPID:pve02:00004248:004B86D3:593AA5C9:qmstart:100:root@pam:
Jun 09 15:42:33 pve02 pve-ha-lrm[16968]: start VM 100: UPID:pve02:00004248:004B86D3:593AA5C9:qmstart:100:root@pam:
Jun 09 15:42:38 pve02 pve-ha-lrm[16967]: Task 'UPID:pve02:00004248:004B86D3:593AA5C9:qmstart:100:root@pam:' still active, waiting
Jun 09 15:42:40 pve02 pve-ha-lrm[16967]: <root@pam> end task UPID:pve02:00004248:004B86D3:593AA5C9:qmstart:100:root@pam: OK
root@pve02:/etc/pve/ha#

and even strange:

root@pve03:~# journalctl --since "2017-06-09" --until "2017-06-10" -u 'pve-ha-*'
-- Logs begin at Tue 2017-06-06 21:07:08 CEST, end at Fri 2017-06-09 15:58:54 CEST. --
Jun 09 00:41:26 pve03 pve-ha-lrm[2166]: unable to write lrm status file - closing file '/etc/pve/nodes/pve03/lrm_status.tmp.2166' failed - Operation not permitted
Jun 09 00:41:31 pve03 pve-ha-crm[2155]: status change slave => wait_for_quorum
Jun 09 00:45:31 pve03 pve-ha-crm[2155]: status change wait_for_quorum => slave
root@pve03:~#
 
Fabian,

I took vm out of ha after another restart .... at 17:06:00 :(

i also checked on all 4 nodes with omping if I may have a multicast problem causing this strange fencing and node restart


I have no glue why this happens ...


omping -c 10000 -i 0.001 -F -q 192.168.221.141 192.168.221.142 192.168.221.143 192.168.221.144



192.168.221.142 : unicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.010/0.032/0.169/0.020
192.168.221.142 : multicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.012/0.040/0.181/0.023
192.168.221.143 : unicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.010/0.039/0.171/0.022
192.168.221.143 : multicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.012/0.043/0.171/0.022
192.168.221.144 : unicast, xmt/rcv/%loss = 9252/9252/0%, min/avg/max/std-dev = 0.010/0.030/0.174/0.020
192.168.221.144 : multicast, xmt/rcv/%loss = 9252/9252/0%, min/avg/max/std-dev = 0.012/0.037/0.180/0.022


192.168.221.141 : unicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.011/0.043/0.207/0.023
192.168.221.141 : multicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.014/0.049/0.215/0.024
192.168.221.143 : unicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.010/0.035/0.144/0.021
192.168.221.143 : multicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.011/0.037/0.162/0.022
192.168.221.144 : unicast, xmt/rcv/%loss = 9554/9554/0%, min/avg/max/std-dev = 0.010/0.043/0.183/0.023
192.168.221.144 : multicast, xmt/rcv/%loss = 9554/9554/0%, min/avg/max/std-dev = 0.012/0.045/0.184/0.023


192.168.221.141 : unicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.010/0.050/0.214/0.026
192.168.221.141 : multicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.013/0.053/0.223/0.025
192.168.221.142 : unicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.010/0.042/0.153/0.022
192.168.221.142 : multicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.012/0.046/0.159/0.022
192.168.221.144 : unicast, xmt/rcv/%loss = 9814/9814/0%, min/avg/max/std-dev = 0.010/0.032/0.168/0.021
192.168.221.144 : multicast, xmt/rcv/%loss = 9814/9814/0%, min/avg/max/std-dev = 0.012/0.035/0.177/0.021



192.168.221.141 : unicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.010/0.043/0.182/0.023
192.168.221.141 : multicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.014/0.049/0.191/0.024
192.168.221.142 : unicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.010/0.037/0.169/0.022
192.168.221.142 : multicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.012/0.042/0.175/0.024
192.168.221.143 : unicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.010/0.030/0.154/0.019
192.168.221.143 : multicast, xmt/rcv/%loss = 10000/10000/0%, min/avg/max/std-dev = 0.012/0.033/0.173/0.019
 
Hi Fabian no more unexpected restart attempts after i removed vm100 from ha !

I now put it back into ha without group all ... let's see if this behavior returns :(

Regards

Gerhard
 
Fabian,

I manually migrated vm100 to node4 at 10:25,
Sadly, after 2 hours node1 restarted for a unknown reason...

how to solve this ? i have definitely no glue :(


root@pve03:~# journalctl --since "2017-06-12" --until "2017-06-13" -u 'pve-ha-*'
-- Logs begin at Tue 2017-06-06 21:07:08 CEST, end at Mon 2017-06-12 15:22:17 CEST. --
Jun 12 10:00:17 pve03 pve-ha-crm[2155]: successfully acquired lock 'ha_manager_lock'
Jun 12 10:00:17 pve03 pve-ha-crm[2155]: watchdog active
Jun 12 10:00:17 pve03 pve-ha-crm[2155]: status change wait_for_quorum => master
Jun 12 10:00:17 pve03 pve-ha-crm[2155]: adding new service 'vm:100' on node 'pve01'
Jun 12 10:24:07 pve03 pve-ha-crm[2155]: got crm command: migrate vm:100 pve04
Jun 12 10:24:07 pve03 pve-ha-crm[2155]: migrate service 'vm:100' to node 'pve04'
Jun 12 10:24:07 pve03 pve-ha-crm[2155]: service 'vm:100': state changed from 'started' to 'migrate' (node = pve01, target = pve04)
Jun 12 10:25:27 pve03 pve-ha-crm[2155]: service 'vm:100': state changed from 'migrate' to 'started' (node = pve04)
Jun 12 12:13:18 pve03 pve-ha-crm[2155]: node 'pve01': state changed from 'online' => 'unknown'
Jun 12 12:18:48 pve03 pve-ha-crm[2155]: node 'pve01': state changed from 'unknown' => 'online'


root@pve01:~# journalctl --since "2017-06-12" --until "2017-06-13" -u 'pve*'
-- Logs begin at Mon 2017-06-12 12:18:33 CEST, end at Mon 2017-06-12 15:25:01 CEST. --
Jun 12 12:18:34 pve01 systemd[1]: Starting Proxmox VE firewall logger...
Jun 12 12:18:34 pve01 systemd[1]: Starting Proxmox VE Login Banner...
Jun 12 12:18:34 pve01 systemd[1]: Starting Commit Proxmox VE network changes...
Jun 12 12:18:34 pve01 mv[1364]: /bin/mv: cannot stat â/etc/network/interfaces.newâ: No such file or directory
Jun 12 12:18:34 pve01 systemd[1]: Started Commit Proxmox VE network changes.
Jun 12 12:18:34 pve01 pvepw-logger[1381]: starting pvefw logger
Jun 12 12:18:34 pve01 systemd[1]: Started Proxmox VE firewall logger.
Jun 12 12:18:35 pve01 systemd[1]: Started Proxmox VE Login Banner.
Jun 12 12:18:39 pve01 systemd[1]: Starting The Proxmox VE cluster filesystem...
Jun 12 12:18:39 pve01 pmxcfs[2004]: [quorum] crit: quorum_initialize failed: 2
Jun 12 12:18:39 pve01 pmxcfs[2004]: [quorum] crit: can't initialize service
Jun 12 12:18:39 pve01 pmxcfs[2004]: [confdb] crit: cmap_initialize failed: 2
Jun 12 12:18:39 pve01 pmxcfs[2004]: [confdb] crit: can't initialize service
Jun 12 12:18:39 pve01 pmxcfs[2004]: [dcdb] crit: cpg_initialize failed: 2
Jun 12 12:18:39 pve01 pmxcfs[2004]: [dcdb] crit: can't initialize service
Jun 12 12:18:39 pve01 pmxcfs[2004]: [status] crit: cpg_initialize failed: 2
Jun 12 12:18:39 pve01 pmxcfs[2004]: [status] crit: can't initialize service
Jun 12 12:18:40 pve01 systemd[1]: Started The Proxmox VE cluster filesystem.
Jun 12 12:18:40 pve01 systemd[1]: Starting PVE Status Daemon...
Jun 12 12:18:40 pve01 systemd[1]: Starting Proxmox VE firewall...
Jun 12 12:18:40 pve01 pve-firewall[2234]: starting server
Jun 12 12:18:40 pve01 systemd[1]: Started Proxmox VE firewall.
Jun 12 12:18:40 pve01 pvestatd[2236]: starting server
Jun 12 12:18:40 pve01 systemd[1]: Started PVE Status Daemon.
Jun 12 12:18:40 pve01 systemd[1]: Starting PVE API Daemon...
Jun 12 12:18:41 pve01 pvedaemon[2494]: starting server
Jun 12 12:18:41 pve01 pvedaemon[2494]: starting 3 worker(s)
Jun 12 12:18:41 pve01 pvedaemon[2494]: worker 2501 started
Jun 12 12:18:41 pve01 pvedaemon[2494]: worker 2502 started
Jun 12 12:18:41 pve01 pvedaemon[2494]: worker 2503 started
Jun 12 12:18:41 pve01 systemd[1]: Started PVE API Daemon.
Jun 12 12:18:41 pve01 systemd[1]: Starting PVE Cluster Ressource Manager Daemon...
Jun 12 12:18:41 pve01 pve-ha-crm[2818]: starting server
Jun 12 12:18:41 pve01 pve-ha-crm[2818]: status change startup => wait_for_quorum
Jun 12 12:18:41 pve01 systemd[1]: Started PVE Cluster Ressource Manager Daemon.
Jun 12 12:18:41 pve01 systemd[1]: Starting PVE Local HA Ressource Manager Daemon...
Jun 12 12:18:42 pve01 pve-ha-lrm[3023]: starting server
Jun 12 12:18:42 pve01 pve-ha-lrm[3023]: status change startup => wait_for_agent_lock
Jun 12 12:18:42 pve01 systemd[1]: Started PVE Local HA Ressource Manager Daemon.
Jun 12 12:18:43 pve01 systemd[1]: Starting PVE API Proxy Server...
Jun 12 12:18:43 pve01 pveproxy[4581]: starting server
Jun 12 12:18:43 pve01 pveproxy[4581]: starting 3 worker(s)
Jun 12 12:18:43 pve01 pveproxy[4581]: worker 4582 started
Jun 12 12:18:43 pve01 pveproxy[4581]: worker 4583 started
Jun 12 12:18:43 pve01 pveproxy[4581]: worker 4584 started
Jun 12 12:18:43 pve01 systemd[1]: Started PVE API Proxy Server.
Jun 12 12:18:44 pve01 systemd[1]: Starting PVE VM Manager...
Jun 12 12:18:44 pve01 pve-manager[4701]: <root@pam> starting task UPID:pve01:00001349:00000969:593E6A84:startall::root@pam:
Jun 12 12:18:45 pve01 pmxcfs[2004]: [status] notice: update cluster info (cluster name net4sec1, version = 4)
Jun 12 12:18:45 pve01 pmxcfs[2004]: [status] notice: node has quorum
Jun 12 12:18:45 pve01 pmxcfs[2004]: [dcdb] notice: members: 1/2004, 2/1901, 3/1872, 4/1873
Jun 12 12:18:45 pve01 pmxcfs[2004]: [dcdb] notice: starting data syncronisation
Jun 12 12:18:45 pve01 pmxcfs[2004]: [status] notice: members: 1/2004, 2/1901, 3/1872, 4/1873
Jun 12 12:18:45 pve01 pmxcfs[2004]: [status] notice: starting data syncronisation
Jun 12 12:18:45 pve01 pmxcfs[2004]: [dcdb] notice: received sync request (epoch 1/2004/00000001)
Jun 12 12:18:45 pve01 pmxcfs[2004]: [status] notice: received sync request (epoch 1/2004/00000001)
Jun 12 12:18:45 pve01 pmxcfs[2004]: [dcdb] notice: received all states
Jun 12 12:18:45 pve01 pmxcfs[2004]: [dcdb] notice: leader is 2/1901
Jun 12 12:18:45 pve01 pmxcfs[2004]: [dcdb] notice: synced members: 2/1901, 3/1872, 4/1873
Jun 12 12:18:45 pve01 pmxcfs[2004]: [dcdb] notice: waiting for updates from leader
Jun 12 12:18:45 pve01 pmxcfs[2004]: [dcdb] notice: update complete - trying to commit (got 8 inode updates)
Jun 12 12:18:45 pve01 pmxcfs[2004]: [dcdb] notice: all data is up to date
Jun 12 12:18:45 pve01 pmxcfs[2004]: [status] notice: received all states
Jun 12 12:18:45 pve01 pmxcfs[2004]: [status] notice: all data is up to date
Jun 12 12:18:46 pve01 pve-manager[4701]: <root@pam> end task UPID:pve01:00001349:00000969:593E6A84:startall::root@pam: OK
Jun 12 12:18:46 pve01 systemd[1]: Started PVE VM Manager.
Jun 12 12:18:51 pve01 pve-ha-crm[2818]: status change wait_for_quorum => slave
Jun 12 12:19:03 pve01 pvedaemon[2501]: <root@pam> successful auth for user 'root@pam'
Jun 12 12:33:57 pve01 pvedaemon[2503]: <root@pam> successful auth for user 'root@pam'
Jun 12 12:48:58 pve01 pvedaemon[2502]: <root@pam> successful auth for user 'root@pam'
Jun 12 13:03:59 pve01 pvedaemon[2502]: <root@pam> successful auth for user 'root@pam'
Jun 12 13:15:10 pve01 pveproxy[4584]: worker exit
Jun 12 13:15:10 pve01 pveproxy[4581]: worker 4584 finished
Jun 12 13:15:10 pve01 pveproxy[4581]: starting 1 worker(s)
Jun 12 13:15:10 pve01 pveproxy[4581]: worker 30147 started
Jun 12 13:18:39 pve01 pmxcfs[2004]: [dcdb] notice: data verification successful
Jun 12 13:18:59 pve01 pvedaemon[2502]: <root@pam> successful auth for user 'root@pam'
Jun 12 13:29:14 pve01 pveproxy[4583]: worker exit
Jun 12 13:29:14 pve01 pveproxy[4581]: worker 4583 finished
Jun 12 13:29:14 pve01 pveproxy[4581]: starting 1 worker(s)
Jun 12 13:29:14 pve01 pveproxy[4581]: worker 36718 started
Jun 12 13:34:00 pve01 pvedaemon[2501]: <root@pam> successful auth for user 'root@pam'
Jun 12 13:49:01 pve01 pvedaemon[2501]: <root@pam> successful auth for user 'root@pam'
Jun 12 14:04:01 pve01 pvedaemon[2502]: <root@pam> successful auth for user 'root@pam'
Jun 12 14:13:15 pve01 pveproxy[36718]: worker exit
Jun 12 14:13:15 pve01 pveproxy[4581]: worker 36718 finished
Jun 12 14:13:15 pve01 pveproxy[4581]: starting 1 worker(s)
Jun 12 14:13:15 pve01 pveproxy[4581]: worker 55918 started
Jun 12 14:18:39 pve01 pmxcfs[2004]: [dcdb] notice: data verification successful
Jun 12 14:19:01 pve01 pvedaemon[2501]: <root@pam> successful auth for user 'root@pam'
Jun 12 14:34:02 pve01 pvedaemon[2501]: <root@pam> successful auth for user 'root@pam'
Jun 12 14:44:01 pve01 pvedaemon[2503]: worker exit
Jun 12 14:44:01 pve01 pvedaemon[2494]: worker 2503 finished
Jun 12 14:44:01 pve01 pvedaemon[2494]: starting 1 worker(s)
Jun 12 14:44:01 pve01 pvedaemon[2494]: worker 14814 started
Jun 12 14:49:03 pve01 pvedaemon[2502]: <root@pam> successful auth for user 'root@pam'
Jun 12 14:49:50 pve01 pveproxy[4582]: worker exit
Jun 12 14:49:50 pve01 pveproxy[4581]: worker 4582 finished
Jun 12 14:49:50 pve01 pveproxy[4581]: starting 1 worker(s)
Jun 12 14:49:50 pve01 pveproxy[4581]: worker 17357 started
Jun 12 14:57:20 pve01 pvedaemon[2502]: <root@pam> starting task UPID:pve01:000050D1:000E8E97:593E8FB0:vzstart:101:root@pam:
Jun 12 14:57:20 pve01 pvedaemon[20689]: starting CT 101: UPID:pve01:000050D1:000E8E97:593E8FB0:vzstart:101:root@pam:
Jun 12 14:57:51 pve01 pveproxy[17357]: proxy detected vanished client connection
Jun 12 14:58:03 pve01 pvedaemon[2502]: <root@pam> end task UPID:pve01:000050D1:000E8E97:593E8FB0:vzstart:101:root@pam: OK
Jun 12 14:58:04 pve01 pvestatd[2236]: status update time (33.835 seconds)
Jun 12 15:04:04 pve01 pvedaemon[14814]: <root@pam> successful auth for user 'root@pam'
Jun 12 15:16:23 pve01 pvedaemon[2502]: worker exit
Jun 12 15:16:24 pve01 pvedaemon[2494]: worker 2502 finished
Jun 12 15:16:24 pve01 pvedaemon[2494]: starting 1 worker(s)
Jun 12 15:16:24 pve01 pvedaemon[2494]: worker 28125 started
Jun 12 15:18:01 pve01 pveproxy[30147]: worker exit
Jun 12 15:18:01 pve01 pveproxy[4581]: worker 30147 finished
Jun 12 15:18:01 pve01 pveproxy[4581]: starting 1 worker(s)
Jun 12 15:18:01 pve01 pveproxy[4581]: worker 28708 started
Jun 12 15:18:39 pve01 pmxcfs[2004]: [dcdb] notice: data verification successful
Jun 12 15:19:03 pve01 pvedaemon[2501]: <root@pam> successful auth for user 'root@pam'
Jun 12 15:21:10 pve01 pveproxy[55918]: worker exit
Jun 12 15:21:10 pve01 pveproxy[4581]: worker 55918 finished
Jun 12 15:21:10 pve01 pveproxy[4581]: starting 1 worker(s)
Jun 12 15:21:10 pve01 pveproxy[4581]: worker 29835 started
 
you should probably enable persistent journalling ("mkdir /var/log/journal; systemctl restart systemd-journal"), otherwise the journal only contains the logs of the current boot. you still have HA enabled, so my best guess is your node gets fenced. maybe multicast in your network is not stable at all times? could you try the longer running test from https://pve.proxmox.com/pve-docs/pve-admin-guide.html#_cluster_network ?
 
Fabian,

I just activated persistent journal.

mkdir /var/log/journal; systemctl restart systemd-journald.service

cabling is Mellanox QSFP 3m Cable to Mellanox switch sx1012 .. 12 port QSFP ...
I see no errors on Mellanox switch and not on Mellanox cards in the nodes

Regards

Gerhard
on all 4 nodes
omping -c 600 -i 1 -q 192.168.221.141 192.168.221.142 192.168.221.143 192.168.221.144


node1
192.168.221.142 : unicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.021/0.095/0.211/0.030
192.168.221.142 : multicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.035/0.100/0.191/0.032
192.168.221.143 : unicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.028/0.085/0.180/0.033
192.168.221.143 : multicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.033/0.110/0.189/0.035
192.168.221.144 : unicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.024/0.090/0.169/0.031
192.168.221.144 : multicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.030/0.092/0.171/0.027


node2
192.168.221.141 : unicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.023/0.105/0.202/0.034
192.168.221.141 : multicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.041/0.120/0.224/0.036
192.168.221.143 : unicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.026/0.084/0.177/0.031
192.168.221.143 : multicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.030/0.090/0.200/0.032
192.168.221.144 : unicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.025/0.083/0.185/0.031
192.168.221.144 : multicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.029/0.089/0.186/0.032

node3
192.168.221.141 : unicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.024/0.104/0.201/0.032
192.168.221.141 : multicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.037/0.102/0.212/0.033
192.168.221.142 : unicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.019/0.085/0.160/0.028
192.168.221.142 : multicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.022/0.083/0.175/0.031
192.168.221.144 : unicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.026/0.084/0.158/0.031
192.168.221.144 : multicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.029/0.094/0.168/0.028

node4
192.168.221.141 : unicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.026/0.108/0.227/0.038
192.168.221.141 : multicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.038/0.110/0.221/0.038
192.168.221.142 : unicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.020/0.088/0.183/0.032
192.168.221.142 : multicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.024/0.099/0.190/0.034
192.168.221.143 : unicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.027/0.101/0.212/0.040
192.168.221.143 : multicast, xmt/rcv/%loss = 600/600/0%, min/avg/max/std-dev = 0.032/0.102/0.201/0.040
 
Hi Fabian,

I updated firmware of Mellanox 3xg-pro to latest release :
Code: 
 mstflint -d 81:00.0 q
Image type:      FS2
FW Version:      2.40.7000
FW Release Date: 22.3.2017
Product Version: 02.40.70.00
Rom Info:        type=PXE version=3.4.746 devid=4103 proto=0xff
Device ID:       4103
Description:     Node             Port1            Port2            Sys image
GUIDs:           ffffffffffffffff ffffffffffffffff ffffffffffffffff ffffffffffffffff
MACs:                                 248a07e26070     248a07e26071
VSD:
PSID:            MT_1090111023

so no more unexpected restarts occurred !

I also changed corosync to use beside 40GbitE ring 0 a ring1 on 10GigE ...
Code: 
logging {
  debug: off
  to_syslog: yes
}

nodelist {
  node {
    name: pve04
    nodeid: 4
    quorum_votes: 1
    ring0_addr: 192.168.221.144
    ring1_addr: 192.168.111.144
  }

  node {
    name: pve03
    nodeid: 3
    quorum_votes: 1
    ring0_addr: 192.168.221.143
    ring1_addr: 192.168.111.143
  }

  node {
    name: pve01
    nodeid: 1
    quorum_votes: 1
    ring0_addr: 192.168.221.141
    ring1_addr: 192.168.111.141
  }

  node {
    name: pve02
    nodeid: 2
    quorum_votes: 1
    ring0_addr: 192.168.221.142
    ring1_addr: 192.168.111.142
  }

}

quorum {
  provider: corosync_votequorum
}

totem {
  cluster_name: net4sec1
  config_version: 8
  ip_version: ipv4
  rrp_mode: passive
  secauth: on
  version: 2
  interface {
    bindnetaddr: 192.168.221.141
    ringnumber: 0
  }
  interface {
    bindnetaddr: 192.168.111.141
    ringnumber: 1
  }

}

but got strange entries ( on all 4 nodes !), from TOTEM which in turn have no negative results on the cluster... but should i be concerned ?
Code: 
Jun 20 04:07:46 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:07:47 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:07:58 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:07:58 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:08:09 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:08:10 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:08:20 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:08:21 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:08:31 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:08:32 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:08:43 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:08:44 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:08:55 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:08:56 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:09:06 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:09:07 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:09:18 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:09:19 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:09:29 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:09:30 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:09:40 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:09:41 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:09:52 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:09:53 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:10:03 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:10:04 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:10:15 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:10:16 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:10:26 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:10:27 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:10:38 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:10:39 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:10:50 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:10:51 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:11:03 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:11:04 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:11:14 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:11:15 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:11:26 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:11:27 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0
Jun 20 04:11:37 pve04 corosync[2073]: [TOTEM ] Marking ringid 0 interface 192.168.221.144 FAULTY
Jun 20 04:11:38 pve04 corosync[2073]: [TOTEM ] Automatically recovered ring 0

[/CODE
 
that sounds like corosync is not happy with your 40GbE.. are you sure it worked before adding the ring1?
 
You must log in or register to reply here.

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Quick Navigation

Home Get Subscription Wiki Downloads Proxmox Customer Portal About

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!
Community platform by XenForo® © 2010-2024 XenForo Ltd.
Top Bottom