OpenNebula suddenly dies after upgrade to 5.4

Community Support
1

We have OpenNebula 5.2.1 installed (which was upgraded to 5.2.1 from version 4.6.0).
When new version 5.4 was released, we decided to upgrade our installation.
But after full upgrade process (http://docs.opennebula.org/5.4/intro_release_notes/upgrades/upgrade_52.html, http://docs.opennebula.org/5.4/deployment/opennebula_installation/frontend_installation.html#ignc) when we start one ($ one start) after ~30 second oned suddenly dies and we see such strings in our logs.

/var/log/syslog
Jul 31 15:28:05 on kernel: [ 2009.104310] oned[24712]: segfault at 9 ip 000000000056cd36 sp 00007f8f7a7fb5e0 error 4 in oned[400000+2fb000]
Jul 31 15:39:10 on kernel: [ 2674.875929] oned[603]: segfault at 7fbfcc0003e8 ip 00007fbfcc0003e8 sp 00007fbffdffa5d8 error 15

After we come back to version 5.2.1 (restore database, /etc/one backup, original OpenNebula 5.2.1 packages), we have working installation.

Debian Jessie 8.9 x64
root@on:/var/log/one# dpkg --get-selections | grep nebula
opennebula install
opennebula-common install
opennebula-flow install
opennebula-sunstone install
opennebula-tools install
ruby-opennebula install

2

About the fail, do you have the log files? also do you have access to the core files?

3

Yes, I have root access on all nodes. Which logs are necessary for You?

4

Just oned.log from the frontend. and maybe you have something coredumpctl for oned… This has to be the 5.4 oned.log that crashed,

THANK YOU!!

5

root@on:/var/log/one# cat /var/log/one/oned.log
Tue Aug 1 17:00:07 2017 [Z0][ONE][I]: Starting OpenNebula 5.4.0

 OpenNebula Configuration File

AUTH_MAD=AUTHN=ssh,x509,ldap,server_cipher,server_x509,EXECUTABLE=one_auth_mad
AUTH_MAD_CONF=DRIVER_MANAGED_GROUPS=NO,MAX_TOKEN_TIME=-1,NAME=core,PASSWORD_CHANGE=YES
AUTH_MAD_CONF=DRIVER_MANAGED_GROUPS=NO,MAX_TOKEN_TIME=-1,NAME=public,PASSWORD_CHANGE=NO
AUTH_MAD_CONF=DRIVER_MANAGED_GROUPS=NO,MAX_TOKEN_TIME=-1,NAME=ssh,PASSWORD_CHANGE=YES
AUTH_MAD_CONF=DRIVER_MANAGED_GROUPS=NO,MAX_TOKEN_TIME=-1,NAME=x509,PASSWORD_CHANGE=NO
AUTH_MAD_CONF=DRIVER_MANAGED_GROUPS=YES,MAX_TOKEN_TIME=86400,NAME=ldap,PASSWORD_CHANGE=YES
AUTH_MAD_CONF=DRIVER_MANAGED_GROUPS=NO,MAX_TOKEN_TIME=-1,NAME=server_cipher,PASSWORD_CHANGE=NO
AUTH_MAD_CONF=DRIVER_MANAGED_GROUPS=NO,MAX_TOKEN_TIME=-1,NAME=server_x509,PASSWORD_CHANGE=NO
DATASTORE_CAPACITY_CHECK=yes
DATASTORE_LOCATION=/var/lib/one//datastores
DATASTORE_MAD=ARGUMENTS=-t 15 -d dummy,fs,lvm,ceph,dev,iscsi_libvirt,vcenter -s shared,ssh,ceph,fs_lvm,qcow2,vcenter,EXECUTABLE=one_datastore
DB=BACKEND=mysql,DB_NAME=opennebula,PASSWD=kar123kar,PORT=0,SERVER=localhost,USER=oneadmin
DEFAULT_AUTH=ldap
DEFAULT_CDROM_DEVICE_PREFIX=hd
DEFAULT_COST=CPU_COST=0,DISK_COST=0,MEMORY_COST=0
DEFAULT_DEVICE_PREFIX=hd
DEFAULT_IMAGE_PERSISTENT=
DEFAULT_IMAGE_PERSISTENT_NEW=
DEFAULT_IMAGE_TYPE=OS
DEFAULT_UMASK=177
DS_MAD_CONF=MARKETPLACE_ACTIONS=export,NAME=ceph,PERSISTENT_ONLY=NO,REQUIRED_ATTRS=DISK_TYPE,BRIDGE_LIST
DS_MAD_CONF=NAME=dev,PERSISTENT_ONLY=YES,REQUIRED_ATTRS=DISK_TYPE
DS_MAD_CONF=NAME=iscsi_libvirt,PERSISTENT_ONLY=YES,REQUIRED_ATTRS=DISK_TYPE,ISCSI_HOST
DS_MAD_CONF=NAME=dummy,PERSISTENT_ONLY=NO,REQUIRED_ATTRS=
DS_MAD_CONF=MARKETPLACE_ACTIONS=export,NAME=fs,PERSISTENT_ONLY=NO,REQUIRED_ATTRS=
DS_MAD_CONF=NAME=lvm,PERSISTENT_ONLY=NO,REQUIRED_ATTRS=DISK_TYPE,BRIDGE_LIST
DS_MAD_CONF=MARKETPLACE_ACTIONS=export,NAME=vcenter,PERSISTENT_ONLY=NO,REQUIRED_ATTRS=VCENTER_INSTANCE_ID, VCENTER_DS_REF, VCENTER_DC_REF
DS_MAD_CONF=NAME=shared,PERSISTENT_ONLY=NO,REQUIRED_ATTRS=
DS_MAD_CONF=NAME=ssh,PERSISTENT_ONLY=NO,REQUIRED_ATTRS=
DS_MAD_CONF=NAME=vmfs,PERSISTENT_ONLY=NO,REQUIRED_ATTRS=BRIDGE_LIST
ENABLE_OTHER_PERMISSIONS=YES
FEDERATION=MASTER_ONED=,MODE=STANDALONE,SERVER_ID=-1,ZONE_ID=0
HM_MAD=EXECUTABLE=one_hm
HOST_MONITORING_EXPIRATION_TIME=43200
HOST_PER_INTERVAL=15
IMAGE_RESTRICTED_ATTR=SOURCE
IM_MAD=ARGUMENTS=-p 4124 -f 5 -t 50 -i 20,EXECUTABLE=collectd,NAME=collectd
IM_MAD=ARGUMENTS=-r 3 -t 15 kvm,EXECUTABLE=one_im_ssh,NAME=kvm,SUNSTONE_NAME=KVM
IM_MAD=ARGUMENTS=-c -t 15 -r 0 vcenter,EXECUTABLE=one_im_sh,NAME=vcenter,SUNSTONE_NAME=VMWare vCenter
INHERIT_DATASTORE_ATTR=CEPH_HOST
INHERIT_DATASTORE_ATTR=CEPH_SECRET
INHERIT_DATASTORE_ATTR=CEPH_KEY
INHERIT_DATASTORE_ATTR=CEPH_USER
INHERIT_DATASTORE_ATTR=CEPH_CONF
INHERIT_DATASTORE_ATTR=POOL_NAME
INHERIT_DATASTORE_ATTR=ISCSI_USER
INHERIT_DATASTORE_ATTR=ISCSI_USAGE
INHERIT_DATASTORE_ATTR=ISCSI_HOST
INHERIT_DATASTORE_ATTR=GLUSTER_HOST
INHERIT_DATASTORE_ATTR=GLUSTER_VOLUME
INHERIT_DATASTORE_ATTR=DISK_TYPE
INHERIT_DATASTORE_ATTR=ALLOW_ORPHANS
INHERIT_DATASTORE_ATTR=VCENTER_ADAPTER_TYPE
INHERIT_DATASTORE_ATTR=VCENTER_DISK_TYPE
INHERIT_DATASTORE_ATTR=VCENTER_DS_REF
INHERIT_DATASTORE_ATTR=VCENTER_DS_IMAGE_DIR
INHERIT_DATASTORE_ATTR=VCENTER_DS_VOLATILE_DIR
INHERIT_DATASTORE_ATTR=VCENTER_INSTANCE_ID
INHERIT_IMAGE_ATTR=ISCSI_USER
INHERIT_IMAGE_ATTR=ISCSI_USAGE
INHERIT_IMAGE_ATTR=ISCSI_HOST
INHERIT_IMAGE_ATTR=ISCSI_IQN
INHERIT_IMAGE_ATTR=DISK_TYPE
INHERIT_IMAGE_ATTR=VCENTER_ADAPTER_TYPE
INHERIT_IMAGE_ATTR=VCENTER_DISK_TYPE
INHERIT_VNET_ATTR=VLAN_TAGGED_ID
INHERIT_VNET_ATTR=FILTER_IP_SPOOFING
INHERIT_VNET_ATTR=FILTER_MAC_SPOOFING
INHERIT_VNET_ATTR=MTU
INHERIT_VNET_ATTR=INBOUND_AVG_BW
INHERIT_VNET_ATTR=INBOUND_PEAK_BW
INHERIT_VNET_ATTR=INBOUND_PEAK_KB
INHERIT_VNET_ATTR=OUTBOUND_AVG_BW
INHERIT_VNET_ATTR=OUTBOUND_PEAK_BW
INHERIT_VNET_ATTR=OUTBOUND_PEAK_KB
INHERIT_VNET_ATTR=CONF
INHERIT_VNET_ATTR=BRIDGE_CONF
INHERIT_VNET_ATTR=IP_LINK_CONF
INHERIT_VNET_ATTR=VCENTER_NET_REF
INHERIT_VNET_ATTR=VCENTER_SWITCH_NAME
INHERIT_VNET_ATTR=VCENTER_SWITCH_NPORTS
INHERIT_VNET_ATTR=VCENTER_PORTGROUP_TYPE
INHERIT_VNET_ATTR=VCENTER_CCR_REF
INHERIT_VNET_ATTR=VCENTER_INSTANCE_ID
IPAM_MAD=ARGUMENTS=-t 1 -i dummy,EXECUTABLE=one_ipam
KEEPALIVE_MAX_CONN=30
KEEPALIVE_TIMEOUT=15
LISTEN_ADDRESS=0.0.0.0
LOG=DEBUG_LEVEL=3,SYSTEM=file
LOG_CALL_FORMAT=Req:%i UID:%u %m invoked %l
MAC_PREFIX=02:00
MANAGER_TIMER=15
MARKET_MAD=ARGUMENTS=-t 15 -m http,s3,one,EXECUTABLE=one_market
MARKET_MAD_CONF=APP_ACTIONS=monitor,NAME=one,PUBLIC=yes,REQUIRED_ATTRS=,SUNSTONE_NAME=OpenNebula.org Marketplace
MARKET_MAD_CONF=APP_ACTIONS=create, delete, monitor,NAME=http,REQUIRED_ATTRS=BASE_URL,PUBLIC_DIR,SUNSTONE_NAME=HTTP server
MARKET_MAD_CONF=APP_ACTIONS=create, delete, monitor,NAME=s3,REQUIRED_ATTRS=ACCESS_KEY_ID,SECRET_ACCESS_KEY,REGION,BUCKET,SUNSTONE_NAME=Amazon S3
MAX_CONN=15
MAX_CONN_BACKLOG=15
MESSAGE_SIZE=1073741824
MONITORING_INTERVAL=60
MONITORING_THREADS=50
NETWORK_SIZE=254
PCI_PASSTHROUGH_BUS=0x01
PORT=2633
RAFT=BROADCAST_TIMEOUT_MS=500,ELECTION_TIMEOUT_MS=2500,LOG_PURGE_TIMEOUT=600,LOG_RETENTION=500000,XMLRPC_TIMEOUT_MS=2000
RPC_LOG=NO
SCRIPTS_REMOTE_DIR=/var/tmp/one
SESSION_EXPIRATION_TIME=900
TIMEOUT=15
TM_MAD=ARGUMENTS=-t 15 -d dummy,lvm,shared,fs_lvm,qcow2,ssh,ceph,dev,vcenter,iscsi_libvirt,EXECUTABLE=one_tm
TM_MAD_CONF=CLONE_TARGET=SYSTEM,DS_MIGRATE=YES,LN_TARGET=NONE,NAME=dummy,SHARED=YES
TM_MAD_CONF=CLONE_TARGET=SELF,LN_TARGET=NONE,NAME=lvm,SHARED=YES
TM_MAD_CONF=CLONE_TARGET=SYSTEM,DS_MIGRATE=YES,LN_TARGET=NONE,NAME=shared,SHARED=YES
TM_MAD_CONF=CLONE_TARGET=SYSTEM,DRIVER=raw,LN_TARGET=SYSTEM,NAME=fs_lvm,SHARED=YES
TM_MAD_CONF=CLONE_TARGET=SYSTEM,DRIVER=qcow2,LN_TARGET=NONE,NAME=qcow2,SHARED=YES
TM_MAD_CONF=CLONE_TARGET=SYSTEM,DS_MIGRATE=YES,LN_TARGET=SYSTEM,NAME=ssh,SHARED=NO
TM_MAD_CONF=ALLOW_ORPHANS=yes,CLONE_TARGET=SELF,DRIVER=raw,DS_MIGRATE=NO,LN_TARGET=NONE,NAME=ceph,SHARED=YES
TM_MAD_CONF=CLONE_TARGET=SELF,DS_MIGRATE=NO,LN_TARGET=NONE,NAME=iscsi_libvirt,SHARED=YES
TM_MAD_CONF=CLONE_TARGET=NONE,LN_TARGET=NONE,NAME=dev,SHARED=YES
TM_MAD_CONF=CLONE_TARGET=SYSTEM,LN_TARGET=NONE,NAME=vcenter,SHARED=YES
TM_MAD_CONF=CLONE_TARGET=SYSTEM,DRIVER=,DS_MIGRATE=NO,LN_TARGET=NONE,NAME=vmfs,SHARED=YES
VLAN_IDS=RESERVED=0, 1, 4095,START=2
VM_ADMIN_OPERATIONS=migrate, delete, recover, retry, deploy, resched
VM_INDIVIDUAL_MONITORING=no
VM_MAD=ARGUMENTS=-t 15 -r 0 kvm,DEFAULT=vmm_exec/vmm_exec_kvm.conf,EXECUTABLE=one_vmm_exec,IMPORTED_VMS_ACTIONS=terminate, terminate-hard, hold, release, suspend,
resume, delete, reboot, reboot-hard, resched, unresched, disk-attach,
disk-detach, nic-attach, nic-detach, snap-create, snap-delete,KEEP_SNAPSHOTS=no,NAME=kvm,SUNSTONE_NAME=KVM,TYPE=kvm
VM_MAD=ARGUMENTS=-p -t 15 -r 0 vcenter -s sh,DEFAULT=vmm_exec/vmm_exec_vcenter.conf,EXECUTABLE=one_vmm_sh,IMPORTED_VMS_ACTIONS=terminate, terminate-hard, hold, release, suspend,
resume, delete, reboot, reboot-hard, resched, unresched, poweroff,
poweroff-hard, disk-attach, disk-detach, nic-attach, nic-detach,
snap-create, snap-delete,KEEP_SNAPSHOTS=yes,NAME=vcenter,SUNSTONE_NAME=VMWare vCenter,TYPE=xml
VM_MANAGE_OPERATIONS=undeploy, hold, release, stop, suspend, resume, reboot,
poweroff, disk-attach, nic-attach, disk-snapshot, terminate, disk-resize,
snapshot, updateconf, rename, resize, update, disk-saveas
VM_MONITORING_EXPIRATION_TIME=14400
VM_PER_INTERVAL=5
VM_RESTRICTED_ATTR=CONTEXT/FILES
VM_RESTRICTED_ATTR=NIC/MAC
VM_RESTRICTED_ATTR=NIC/VLAN_ID
VM_RESTRICTED_ATTR=NIC/BRIDGE
VM_RESTRICTED_ATTR=NIC_DEFAULT/MAC
VM_RESTRICTED_ATTR=NIC_DEFAULT/VLAN_ID
VM_RESTRICTED_ATTR=NIC_DEFAULT/BRIDGE
VM_RESTRICTED_ATTR=CPU_COST
VM_RESTRICTED_ATTR=MEMORY_COST
VM_RESTRICTED_ATTR=DISK_COST
VM_RESTRICTED_ATTR=PCI
VM_RESTRICTED_ATTR=EMULATOR
VM_RESTRICTED_ATTR=RAW
VM_RESTRICTED_ATTR=USER_PRIORITY
VM_SUBMIT_ON_HOLD=NO
VM_USE_OPERATIONS=
VNC_PORTS=START=5900
VNET_RESTRICTED_ATTR=VN_MAD
VNET_RESTRICTED_ATTR=PHYDEV
VNET_RESTRICTED_ATTR=VLAN_ID
VNET_RESTRICTED_ATTR=BRIDGE
VNET_RESTRICTED_ATTR=CONF
VNET_RESTRICTED_ATTR=BRIDGE_CONF
VNET_RESTRICTED_ATTR=IP_LINK_CONF
VNET_RESTRICTED_ATTR=AR/VN_MAD
VNET_RESTRICTED_ATTR=AR/PHYDEV
VNET_RESTRICTED_ATTR=AR/VLAN_ID
VNET_RESTRICTED_ATTR=AR/BRIDGE
VXLAN_IDS=START=2

Tue Aug 1 17:00:07 2017 [Z0][ONE][I]: Log level:3 [0=ERROR,1=WARNING,2=INFO,3=DEBUG]
Tue Aug 1 17:00:07 2017 [Z0][ONE][I]: Support for xmlrpc-c > 1.31: yes
Tue Aug 1 17:00:07 2017 [Z0][ONE][I]: Checking database version.
Tue Aug 1 17:00:07 2017 [Z0][ONE][I]: oned is using version 5.4.0 for local_db_versioning
Tue Aug 1 17:00:07 2017 [Z0][ONE][I]: oned is using version 5.4.0 for db_versioning
Tue Aug 1 17:00:07 2017 [Z0][ACL][I]: Starting ACL Manager…
Tue Aug 1 17:00:07 2017 [Z0][ACL][I]: ACL Manager started.
Tue Aug 1 17:00:07 2017 [Z0][HKM][I]: Starting Hook Manager…
Tue Aug 1 17:00:07 2017 [Z0][HKM][I]: Loading Hook Manager driver.
Tue Aug 1 17:00:07 2017 [Z0][HKM][I]: Hook Manager started.
Tue Aug 1 17:00:07 2017 [Z0][HKM][I]: Hook Manager loaded
Tue Aug 1 17:00:07 2017 [Z0][ONE][I]: oned started in solo mode.
Tue Aug 1 17:00:07 2017 [Z0][RCM][I]: Starting Raft Consensus Manager…
Tue Aug 1 17:00:07 2017 [Z0][FRM][I]: Starting Federation Replica Manager…
Tue Aug 1 17:00:07 2017 [Z0][RCM][I]: Raft Consensus Manager started.
Tue Aug 1 17:00:07 2017 [Z0][FRM][I]: Federation Replica Manger started.
Tue Aug 1 17:00:07 2017 [Z0][VMM][I]: Starting Virtual Machine Manager…
Tue Aug 1 17:00:07 2017 [Z0][LCM][I]: Starting Life-cycle Manager…
Tue Aug 1 17:00:07 2017 [Z0][VMM][I]: Virtual Machine Manager started.
Tue Aug 1 17:00:07 2017 [Z0][LCM][I]: Life-cycle Manager started.
Tue Aug 1 17:00:07 2017 [Z0][InM][I]: Starting Information Manager…
Tue Aug 1 17:00:07 2017 [Z0][InM][I]: Information Manager started.
Tue Aug 1 17:00:07 2017 [Z0][TrM][I]: Starting Transfer Manager…
Tue Aug 1 17:00:07 2017 [Z0][DiM][I]: Starting Dispatch Manager…
Tue Aug 1 17:00:07 2017 [Z0][TrM][I]: Transfer Manager started.
Tue Aug 1 17:00:07 2017 [Z0][DiM][I]: Dispatch Manager started.
Tue Aug 1 17:00:07 2017 [Z0][AuM][I]: Starting Auth Manager…
Tue Aug 1 17:00:07 2017 [Z0][AuM][I]: Authorization Manager started.
Tue Aug 1 17:00:07 2017 [Z0][ImM][I]: Starting Image Manager…
Tue Aug 1 17:00:07 2017 [Z0][ImM][I]: Image Manager started.
Tue Aug 1 17:00:07 2017 [Z0][ImM][I]: Starting Marketplace Manager…
Tue Aug 1 17:00:07 2017 [Z0][MKP][I]: Marketplace Manager started.
Tue Aug 1 17:00:07 2017 [Z0][IPM][I]: Starting IPAM Manager…
Tue Aug 1 17:00:07 2017 [Z0][IPM][I]: IPAM Manager started.
Tue Aug 1 17:00:09 2017 [Z0][VMM][I]: Loading Virtual Machine Manager drivers.
Tue Aug 1 17:00:09 2017 [Z0][VMM][I]: Loading driver: kvm (KVM)
Tue Aug 1 17:00:09 2017 [Z0][VMM][E]: Wrong action: snap-create
Tue Aug 1 17:00:09 2017 [Z0][VMM][E]: Wrong action: snap-delete
Tue Aug 1 17:00:10 2017 [Z0][VMM][I]: Driver kvm loaded.
Tue Aug 1 17:00:10 2017 [Z0][VMM][I]: Loading driver: vcenter (XML)
Tue Aug 1 17:00:10 2017 [Z0][VMM][E]: Wrong action: snap-create
Tue Aug 1 17:00:10 2017 [Z0][VMM][E]: Wrong action: snap-delete
Tue Aug 1 17:00:10 2017 [Z0][VMM][I]: Driver vcenter loaded.
Tue Aug 1 17:00:10 2017 [Z0][InM][I]: Loading Information Manager drivers.
Tue Aug 1 17:00:10 2017 [Z0][InM][I]: Loading driver: collectd
Tue Aug 1 17:00:10 2017 [Z0][InM][I]: Driver collectd loaded
Tue Aug 1 17:00:10 2017 [Z0][InM][I]: Loading driver: kvm
Tue Aug 1 17:00:10 2017 [Z0][InM][I]: Driver kvm loaded
Tue Aug 1 17:00:10 2017 [Z0][InM][I]: Loading driver: vcenter
Tue Aug 1 17:00:10 2017 [Z0][InM][I]: Driver vcenter loaded
Tue Aug 1 17:00:10 2017 [Z0][TM][I]: Loading Transfer Manager driver.
Tue Aug 1 17:00:10 2017 [Z0][TM][I]: Transfer manager driver loaded
Tue Aug 1 17:00:10 2017 [Z0][ImM][I]: Loading Image Manager driver.
Tue Aug 1 17:00:10 2017 [Z0][ImM][I]: Image Manager loaded
Tue Aug 1 17:00:10 2017 [Z0][MKP][I]: Loading Marketplace Manager driver.
Tue Aug 1 17:00:11 2017 [Z0][MKP][I]: Marketplace Manager loaded
Tue Aug 1 17:00:11 2017 [Z0][IPM][I]: Loading IPAM Manager driver.
Tue Aug 1 17:00:11 2017 [Z0][IPM][I]: IPAM Manager loaded
Tue Aug 1 17:00:11 2017 [Z0][AuM][I]: Loading Auth. Manager driver.
Tue Aug 1 17:00:11 2017 [Z0][AuM][I]: Auth Manager loaded
Tue Aug 1 17:00:11 2017 [Z0][ReM][I]: Starting Request Manager…
Tue Aug 1 17:00:11 2017 [Z0][ReM][I]: Starting XML-RPC server, port 2633 …
Tue Aug 1 17:00:11 2017 [Z0][ReM][I]: Request Manager started.
Tue Aug 1 17:00:13 2017 [Z0][ReM][D]: Req:9072 UID:0 one.system.config invoked
Tue Aug 1 17:00:13 2017 [Z0][ReM][D]: Req:9072 UID:0 one.system.config result SUCCESS, "<AUTH_MAD>…"
Tue Aug 1 17:00:15 2017 [Z0][InM][D]: Host node2 (1) successfully monitored.
Tue Aug 1 17:00:15 2017 [Z0][VMM][D]: VM 248 successfully monitored: STATE=a CPU=10.19 MEMORY=4194304 NETRX=45240796328 NETTX=32485128 DISKRDBYTES=542150144 DISKWRBYTES=3386170368 DISKRDIOPS=8468 DISKWRIOPS=609088
Tue Aug 1 17:00:15 2017 [Z0][VMM][D]: VM 1248 successfully monitored: STATE=a CPU=9.17 MEMORY=6291456 NETRX=7795943535 NETTX=1029834 DISKRDBYTES=957817954 DISKWRBYTES=5948096512 DISKRDIOPS=100167 DISKWRIOPS=430323
Tue Aug 1 17:00:15 2017 [Z0][VMM][D]: VM 1353 successfully monitored: STATE=a CPU=8.15 MEMORY=2097152 NETRX=7846344197 NETTX=4047478 DISKRDBYTES=2839144960 DISKWRBYTES=3319002624 DISKRDIOPS=164502 DISKWRIOPS=134158
Tue Aug 1 17:00:15 2017 [Z0][VMM][D]: VM 1453 successfully monitored: STATE=a CPU=43.8 MEMORY=33554432 NETRX=45455715771 NETTX=38952371 DISKRDBYTES=976482816 DISKWRBYTES=3739892736 DISKRDIOPS=37951 DISKWRIOPS=914107
Tue Aug 1 17:00:15 2017 [Z0][VMM][D]: VM 1459 successfully monitored: STATE=a CPU=49.92 MEMORY=67108864 NETRX=46044311300 NETTX=271108016 DISKRDBYTES=777558528 DISKWRBYTES=49238375424 DISKRDIOPS=28276 DISKWRIOPS=2593937
Tue Aug 1 17:00:15 2017 [Z0][VMM][D]: VM 1751 successfully monitored: STATE=a CPU=2.04 MEMORY=2104496 NETRX=173623651 NETTX=19512194 DISKRDBYTES=2757950976 DISKWRBYTES=2672941568 DISKRDIOPS=135229 DISKWRIOPS=257903
Tue Aug 1 17:00:15 2017 [Z0][VMM][D]: VM 1752 successfully monitored: STATE=a CPU=1.02 MEMORY=2101432 NETRX=173620473 NETTX=19524356 DISKRDBYTES=2806717440 DISKWRBYTES=2890356224 DISKRDIOPS=136771 DISKWRIOPS=270707
Tue Aug 1 17:00:20 2017 [Z0][InM][D]: Host node1 (0) successfully monitored.
Tue Aug 1 17:00:20 2017 [Z0][VMM][D]: VM 1185 successfully monitored: STATE=a CPU=3.09 MEMORY=4227184 NETRX=81672464055 NETTX=3661161235 DISKRDBYTES=1821240588 DISKWRBYTES=70083159040 DISKRDIOPS=225327 DISKWRIOPS=3084419
Tue Aug 1 17:00:20 2017 [Z0][VMM][D]: VM 1187 successfully monitored: STATE=a CPU=4.12 MEMORY=2097152 NETRX=45237429906 NETTX=15079048 DISKRDBYTES=105780800 DISKWRBYTES=7239254016 DISKRDIOPS=26278 DISKWRIOPS=1290505
Tue Aug 1 17:00:20 2017 [Z0][VMM][D]: VM 1361 successfully monitored: STATE=a CPU=0.0 MEMORY=4145152 NETRX=80903141659 NETTX=1016816374 DISKRDBYTES=5552362386 DISKWRBYTES=106104012800 DISKRDIOPS=225858 DISKWRIOPS=7870164
Tue Aug 1 17:00:20 2017 [Z0][VMM][D]: VM 1402 successfully monitored: STATE=a CPU=9.27 MEMORY=2127996 NETRX=81521328462 NETTX=738258751 DISKRDBYTES=9271912448 DISKWRBYTES=12966392832 DISKRDIOPS=979832 DISKWRIOPS=1979401
Tue Aug 1 17:00:20 2017 [Z0][VMM][D]: VM 1561 successfully monitored: STATE=a CPU=2.06 MEMORY=1048576 NETRX=7798084557 NETTX=58715 DISKRDBYTES=420557430 DISKWRBYTES=460955648 DISKRDIOPS=43381 DISKWRIOPS=67329
Tue Aug 1 17:00:20 2017 [Z0][VMM][D]: VM 1591 successfully monitored: STATE=a CPU=4.12 MEMORY=1048576 NETRX=68476506439 NETTX=2317294 DISKRDBYTES=52211712 DISKWRBYTES=4108345344 DISKRDIOPS=567 DISKWRIOPS=547707
Tue Aug 1 17:00:20 2017 [Z0][VMM][D]: VM 1610 successfully monitored: STATE=a CPU=3.09 MEMORY=2097152 NETRX=7764589096 NETTX=1734768 DISKRDBYTES=104329430 DISKWRBYTES=76038144 DISKRDIOPS=43905 DISKWRIOPS=10252
Tue Aug 1 17:00:20 2017 [Z0][VMM][D]: VM 1612 successfully monitored: STATE=a CPU=7.21 MEMORY=2097152 NETRX=68438746913 NETTX=23335186 DISKRDBYTES=1243287552 DISKWRBYTES=1438043136 DISKRDIOPS=39594 DISKWRIOPS=266120
Tue Aug 1 17:00:21 2017 [Z0][VMM][D]: VM 1613 successfully monitored: STATE=a CPU=5.15 MEMORY=4194304 NETRX=68444902611 NETTX=10791668 DISKRDBYTES=23183360 DISKWRBYTES=10223796224 DISKRDIOPS=375 DISKWRIOPS=1105733
Tue Aug 1 17:00:21 2017 [Z0][VMM][D]: VM 1630 successfully monitored: STATE=a CPU=102.96 MEMORY=4194304 NETRX=7763642798 NETTX=6600311 DISKRDBYTES=884729954 DISKWRBYTES=10779724800 DISKRDIOPS=92634 DISKWRIOPS=1007047
Tue Aug 1 17:00:21 2017 [Z0][VMM][D]: VM 1637 successfully monitored: STATE=a CPU=3.09 MEMORY=4194304 NETRX=7761912624 NETTX=826598 DISKRDBYTES=149280964 DISKWRBYTES=106779648 DISKRDIOPS=50430 DISKWRIOPS=12905
Tue Aug 1 17:00:21 2017 [Z0][VMM][D]: VM 1654 successfully monitored: STATE=a CPU=0.0 MEMORY=4194304 NETRX=3096942 NETTX=0 DISKRDBYTES=766464 DISKWRBYTES=0 DISKRDIOPS=1497 DISKWRIOPS=0
Tue Aug 1 17:00:21 2017 [Z0][VMM][D]: VM 1658 successfully monitored: STATE=a CPU=24.71 MEMORY=2097152 NETRX=68461494435 NETTX=17213418 DISKRDBYTES=49152 DISKWRBYTES=15513067520 DISKRDIOPS=12 DISKWRIOPS=1819137
Tue Aug 1 17:00:21 2017 [Z0][VMM][D]: VM 1745 successfully monitored: STATE=a CPU=58.69 MEMORY=4194304 NETRX=25604673 NETTX=600 DISKRDBYTES=0 DISKWRBYTES=723077120 DISKRDIOPS=0 DISKWRIOPS=184214
Tue Aug 1 17:00:21 2017 [Z0][VMM][D]: VM 1748 successfully monitored: STATE=a CPU=0.0 MEMORY=1070184 NETRX=68452670703 NETTX=600 DISKRDBYTES=270336 DISKWRBYTES=15360266240 DISKRDIOPS=27 DISKWRIOPS=1666897
Tue Aug 1 17:00:22 2017 [Z0][InM][D]: Monitoring datastore system (0)
Tue Aug 1 17:00:22 2017 [Z0][MKP][D]: Monitoring marketplace OpenNebula Public (0)
Tue Aug 1 17:00:22 2017 [Z0][InM][D]: Monitoring datastore default (1)
Tue Aug 1 17:00:22 2017 [Z0][InM][D]: Monitoring datastore files (2)
Tue Aug 1 17:00:22 2017 [Z0][ImM][D]: Datastore files (2) successfully monitored.
Tue Aug 1 17:00:22 2017 [Z0][ImM][D]: Datastore default (1) successfully monitored.
Tue Aug 1 17:00:22 2017 [Z0][MKP][D]: Marketplace OpenNebula Public (0) successfully monitored.
Tue Aug 1 17:00:24 2017 [Z0][VMM][D]: VM 1172 successfully monitored: DISK_SIZE=[ID=0,SIZE=3138] DISK_SIZE=[ID=1,SIZE=1]
Tue Aug 1 17:00:24 2017 [Z0][VMM][D]: VM 1185 successfully monitored: DISK_SIZE=[ID=0,SIZE=116917] DISK_SIZE=[ID=1,SIZE=1]
Tue Aug 1 17:00:24 2017 [Z0][VMM][D]: VM 1187 successfully monitored: DISK_SIZE=[ID=0,SIZE=3482] DISK_SIZE=[ID=1,SIZE=1]
Tue Aug 1 17:00:24 2017 [Z0][VMM][D]: VM 1191 successfully monitored: DISK_SIZE=[ID=0,SIZE=25572] DISK_SIZE=[ID=1,SIZE=564] DISK_SIZE=[ID=2,SIZE=1]
Tue Aug 1 17:00:24 2017 [Z0][VMM][D]: VM 1248 successfully monitored: DISK_SIZE=[ID=0,SIZE=18993] DISK_SIZE=[ID=1,SIZE=1]
Tue Aug 1 17:00:24 2017 [Z0][VMM][D]: VM 1258 successfully monitored: DISK_SIZE=[ID=0,SIZE=40827] DISK_SIZE=[ID=1,SIZE=1]
Tue Aug 1 17:00:24 2017 [Z0][VMM][D]: VM 1273 successfully monitored: DISK_SIZE=[ID=0,SIZE=6816] DISK_SIZE=[ID=1,SIZE=564] DISK_SIZE=[ID=2,SIZE=1]

6

After oned crash in SSH console.

oneadmin@on:~$ one stop
oned and scheduler stopped
oneadmin@on:~$ one start
Stale .lock detected. Erasing it.
oneadmin@on:~$ *** Error in `/usr/bin/oned’: double free or corruption (!prev): 0x00007fb4a801e1b0 ***

7

root@on:/var/log# coredumpctl dump 6641
PID: 6641 (oned)
UID: 9869 (oneadmin)
GID: 9869 (oneadmin)
Signal: 6 (ABRT)
Timestamp: Вт 2017-08-01 17:07:53 +03 (46s ago)
Command Line: /usr/bin/oned -f
Executable: /usr/bin/oned
Control Group: /system.slice/ssh.service
Unit: ssh.service
Slice: system.slice
Boot ID: aad63f21be9c4e37b5b59913d28db616
Machine ID: f93825527b0b4f31ab13fb93decfd029
Hostname: on
Coredump: /var/lib/systemd/coredump/core.oned.9869.aad63f21be9c4e37b5b59913d28db616.6641.1501596473000000000000.xz
Message: Process 6641 (oned) of user 9869 dumped core.

            Stack trace of thread 6682:
            #0  0x00007f9166d06067 __GI_raise (libc.so.6)
            #1  0x00007f9166d07448 __GI_abort (libc.so.6)
            #2  0x00007f9166d441b4 __libc_message (libc.so.6)
            #3  0x00007f9166d4998e malloc_printerr (libc.so.6)
            #4  0x00007f9166d4a696 _int_free (libc.so.6)
            #5  0x000000000041deaa _ZN12CallbackableD0Ev (oned)
            #6  0x000000000056cd3e _ZN14VirtualMachineD2Ev (oned)
            #7  0x000000000056cea4 _ZN14VirtualMachineD0Ev (oned)
            #8  0x0000000000533597 _ZN7PoolSQL3getEib (oned)
            #9  0x00000000004420af _ZN18VirtualMachinePool3getEib (oned)
            #10 0x0000000000445406 _ZN27VirtualMachineManagerDriver12process_pollEiRKSsb (oned)
            #11 0x000000000053138d monitor_action (oned)
            #12 0x00000000005326a5 _ZNK18ImageManagerDriver8protocolERKSs (oned)
            #13 0x0000000000517df2 _ZN10MadManager8listenerEv (oned)
            #14 0x000000000051732e mad_manager_listener (oned)
            #15 0x00007f91678a6064 start_thread (libpthread.so.0)
            #16 0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6683:
            #0  0x00007f91678aa3f8 pthread_cond_timedwait@@GLIBC_2.3.2 (libpthread.so.0)
            #1  0x00000000005acae5 _ZN13ActionManager4loopER8timespecRK13ActionRequest (oned)
            #2  0x0000000000441b9d _ZN13ActionManager4loopEl (oned)
            #3  0x0000000000529cc1 image_action_loop (oned)
            #4  0x00007f91678a6064 start_thread (libpthread.so.0)
            #5  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6673:
            #0  0x00007f91678aa3f8 pthread_cond_timedwait@@GLIBC_2.3.2 (libpthread.so.0)
            #1  0x00000000005acae5 _ZN13ActionManager4loopER8timespecRK13ActionRequest (oned)
            #2  0x0000000000441b9d _ZN13ActionManager4loopEl (oned)
            #3  0x00000000004368fa vmm_action_loop (oned)
            #4  0x00007f91678a6064 start_thread (libpthread.so.0)
            #5  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6685:
            #0  0x00007f91678aa3f8 pthread_cond_timedwait@@GLIBC_2.3.2 (libpthread.so.0)
            #1  0x00000000005acae5 _ZN13ActionManager4loopER8timespecRK13ActionRequest (oned)
            #2  0x0000000000441b9d _ZN13ActionManager4loopEl (oned)
            #3  0x00000000005d605b marketplace_action_loop (oned)
            #4  0x00007f91678a6064 start_thread (libpthread.so.0)
            #5  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6884:
            #0  0x00007f91678aa04f pthread_cond_wait@@GLIBC_2.3.2 (libpthread.so.0)
            #1  0x00000000005acb3d _ZN13ActionManager4loopER8timespecRK13ActionRequest (oned)
            #2  0x0000000000458a99 _ZN13ActionManager4loopEv (oned)
            #3  0x000000000046a91d rm_action_loop (oned)
            #4  0x00007f91678a6064 start_thread (libpthread.so.0)
            #5  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6684:
            #0  0x00007f9166db2893 __select (libc.so.6)
            #1  0x0000000000517903 _ZN10MadManager8listenerEv (oned)
            #2  0x000000000051732e mad_manager_listener (oned)
            #3  0x00007f91678a6064 start_thread (libpthread.so.0)
            #4  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6678:
            #0  0x00007f91678aa04f pthread_cond_wait@@GLIBC_2.3.2 (libpthread.so.0)
            #1  0x00000000005acb3d _ZN13ActionManager4loopER8timespecRK13ActionRequest (oned)
            #2  0x0000000000458a99 _ZN13ActionManager4loopEv (oned)
            #3  0x00000000004ddf0c tm_action_loop (oned)
            #4  0x00007f91678a6064 start_thread (libpthread.so.0)
            #5  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6687:
            #0  0x00007f91678aa3f8 pthread_cond_timedwait@@GLIBC_2.3.2 (libpthread.so.0)
            #1  0x00000000005acae5 _ZN13ActionManager4loopER8timespecRK13ActionRequest (oned)
            #2  0x0000000000441b9d _ZN13ActionManager4loopEl (oned)
            #3  0x00000000005d98f5 ipamm_action_loop (oned)
            #4  0x00007f91678a6064 start_thread (libpthread.so.0)
            #5  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6641:
            #0  0x00007f91678ad5c9 do_sigwait (libpthread.so.0)
            #1  0x00007f91678ad653 __sigwait (libpthread.so.0)
            #2  0x000000000041b10f _ZN6Nebula5startEb (oned)
            #3  0x0000000000413810 oned_main (oned)
            #4  0x0000000000413b3e main (oned)
            #5  0x00007f9166cf2b45 __libc_start_main (libc.so.6)
            #6  0x000000000041353b _start (oned)
            
            Stack trace of thread 6670:
            #0  0x00007f91678aa04f pthread_cond_wait@@GLIBC_2.3.2 (libpthread.so.0)
            #1  0x00000000005acb3d _ZN13ActionManager4loopER8timespecRK13ActionRequest (oned)
            #2  0x0000000000458a99 _ZN13ActionManager4loopEv (oned)
            #3  0x00000000005e4669 raft_manager_loop (oned)
            #4  0x00007f91678a6064 start_thread (libpthread.so.0)
            #5  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6676:
            #0  0x00007f91678aa3f8 pthread_cond_timedwait@@GLIBC_2.3.2 (libpthread.so.0)
            #1  0x00000000005acae5 _ZN13ActionManager4loopER8timespecRK13ActionRequest (oned)
            #2  0x0000000000441b9d _ZN13ActionManager4loopEl (oned)
            #3  0x000000000046691f im_action_loop (oned)
            #4  0x00007f91678a6064 start_thread (libpthread.so.0)
            #5  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6672:
            #0  0x00007f9166db2893 __select (libc.so.6)
            #1  0x0000000000517903 _ZN10MadManager8listenerEv (oned)
            #2  0x000000000051732e mad_manager_listener (oned)
            #3  0x00007f91678a6064 start_thread (libpthread.so.0)
            #4  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6677:
            #0  0x00007f9166db2893 __select (libc.so.6)
            #1  0x0000000000517903 _ZN10MadManager8listenerEv (oned)
            #2  0x000000000051732e mad_manager_listener (oned)
            #3  0x00007f91678a6064 start_thread (libpthread.so.0)
            #4  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6680:
            #0  0x00007f9166db2893 __select (libc.so.6)
            #1  0x0000000000517903 _ZN10MadManager8listenerEv (oned)
            #2  0x000000000051732e mad_manager_listener (oned)
            #3  0x00007f91678a6064 start_thread (libpthread.so.0)
            #4  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6671:
            #0  0x00007f91678aa04f pthread_cond_wait@@GLIBC_2.3.2 (libpthread.so.0)
            #1  0x00000000005acb3d _ZN13ActionManager4loopER8timespecRK13ActionRequest (oned)
            #2  0x0000000000458a99 _ZN13ActionManager4loopEv (oned)
            #3  0x00000000005eedab frm_loop (oned)
            #4  0x00007f91678a6064 start_thread (libpthread.so.0)
            #5  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6652:
            #0  0x00007f91678aa04f pthread_cond_wait@@GLIBC_2.3.2 (libpthread.so.0)
            #1  0x00000000005acb3d _ZN13ActionManager4loopER8timespecRK13ActionRequest (oned)
            #2  0x0000000000458a99 _ZN13ActionManager4loopEv (oned)
            #3  0x00000000005ab7da hm_action_loop (oned)
            #4  0x00007f91678a6064 start_thread (libpthread.so.0)
            #5  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6651:
            #0  0x00007f9166db2893 __select (libc.so.6)
            #1  0x0000000000517903 _ZN10MadManager8listenerEv (oned)
            #2  0x000000000051732e mad_manager_listener (oned)
            #3  0x00007f91678a6064 start_thread (libpthread.so.0)
            #4  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6885:
            #0  0x00007f9166db0aed poll (libc.so.6)
            #1  0x00000000006055ae waitForConnection (oned)
            #2  0x00000000005fc904 ChanSwitchAccept (oned)
            #3  0x0000000000602da9 acceptAndProcessNextConnection (oned)
            #4  0x00000000005f5e3c setupSignalsAndRunAbyss (oned)
            #5  0x00000000005f5e76 _ZN8xmlrpc_c16serverAbyss_impl3runEv (oned)
            #6  0x00000000005f6209 _ZN8xmlrpc_c11serverAbyss3runEv (oned)
            #7  0x000000000046aabf rm_xml_server_loop (oned)
            #8  0x00007f91678a6064 start_thread (libpthread.so.0)
            #9  0x00007f9166db962d __clone (libc.so.6)
            
            Stack trace of thread 6679:
            #0  0x00007f91678aa04f pthread_cond_wait@@GLIBC_2.3.2 (libpthread.so.0)
            #1  0x00000000005acb3d _ZN13ActionManager4loopER8timespecRK13ActionRequest (oned)
            #2  0x0000000000458a99 _ZN13ActionManager4loopEv (oned)
            #3  0x00000000004d4e92 dm_action_loop (oned)
            #4  0x00007f91678a6064 start_thread (libpthread.so.0)
            #5  0x00007f9166db962d __clone (libc.so.6)

            Stack trace of thread 6675:
            #0  0x00007f9166db2893 __select (libc.so.6)
            #1  0x0000000000517903 _ZN10MadManager8listenerEv (oned)
            #2  0x000000000051732e mad_manager_listener (oned)
            #3  0x00007f91678a6064 start_thread (libpthread.so.0)
            #4  0x00007f9166db962d __clone (libc.so.6)

            Stack trace of thread 6681:
            #0  0x00007f91678aa3f8 pthread_cond_timedwait@@GLIBC_2.3.2 (libpthread.so.0)
            #1  0x00000000005acae5 _ZN13ActionManager4loopER8timespecRK13ActionRequest (oned)
            #2  0x0000000000441b9d _ZN13ActionManager4loopEl (oned)
            #3  0x0000000000508de4 authm_action_loop (oned)
            #4  0x00007f91678a6064 start_thread (libpthread.so.0)
            #5  0x00007f9166db962d __clone (libc.so.6)

            Stack trace of thread 6674:
            #0  0x00007f91678aa04f pthread_cond_wait@@GLIBC_2.3.2 (libpthread.so.0)
            #1  0x00000000005acb3d _ZN13ActionManager4loopER8timespecRK13ActionRequest (oned)
            #2  0x0000000000458a99 _ZN13ActionManager4loopEv (oned)
            #3  0x000000000045822a lcm_action_loop (oned)
            #4  0x00007f91678a6064 start_thread (libpthread.so.0)
            #5  0x00007f9166db962d __clone (libc.so.6)

            Stack trace of thread 6686:
            #0  0x00007f9166db2893 __select (libc.so.6)
            #1  0x0000000000517903 _ZN10MadManager8listenerEv (oned)
            #2  0x000000000051732e mad_manager_listener (oned)
            #3  0x00007f91678a6064 start_thread (libpthread.so.0)
            #4  0x00007f9166db962d __clone (libc.so.6)

Refusing to dump core to tty.

8

It seems that during the migration one of the VMs in node1 was not upgraded correctly, probably the one after 1273. Could you check the list of VMs running in node1 and send me the output of the following command (probably it is better to send me the output in a private message).

For VMs not in 1273, 1258, 1248, 1191, 1187, 1185 and 1172, execute the following SQL command ‘SELECT * from history_pool where vid = <ID_OF_THE_VM>’ I’ll need this from the upgraded DB.

9

Strange behavior … Why wrong action?
Wed Aug 2 10:23:29 2017 [Z0][VMM][I]: Loading Virtual Machine Manager drivers.
Wed Aug 2 10:23:29 2017 [Z0][VMM][I]: Loading driver: kvm (KVM)
Wed Aug 2 10:23:29 2017 [Z0][VMM][E]: Wrong action: snap-create
Wed Aug 2 10:23:29 2017 [Z0][VMM][E]: Wrong action: snap-delete