Hi, I'm having major issues when trying to add a new host into a fresh install of Cloudstack, I have tested in 4.6 and 4.8 and get the same result, in 4.9 the agent can't connect but it does from 4.8 downwards.
>From the logs I see that the management can ssh into the host and issue the cloudstack-setup-agent command with some parameters and it does succeed but after that it tries to insert some values into the mysql cloud database in the "host" table but it fails, after that it tries to send something via API and fails too. **I'm setting this up in VMWare workstation 12 on a laptop with nested virtualization** I followed this guide http://docs.cloudstack.apache.org/projects/cloudstack-installation/en/4.8/management-server/index.html and this one for the host http://docs.cloudstack.apache.org/projects/cloudstack-installation/en/4.8/configuration.html#adding-a-host I checked and have the ports open in management: Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 0.0.0.0:111 0.0.0.0:* LISTEN 1172/rpcbind tcp 0 0 0.0.0.0:20400 0.0.0.0:* LISTEN 10316/java tcp 0 0 0.0.0.0:8080 0.0.0.0:* LISTEN 10316/java tcp 0 0 0.0.0.0:20048 0.0.0.0:* LISTEN 1237/rpc.mountd tcp 0 0 192.168.122.1:53 0.0.0.0:* LISTEN 2073/dnsmasq tcp 0 0 0.0.0.0:44373 0.0.0.0:* LISTEN 1168/rpc.statd tcp 0 0 0.0.0.0:22 0.0.0.0:* LISTEN 1157/sshd tcp 0 0 0.0.0.0:8250 0.0.0.0:* LISTEN 10316/java tcp 0 0 0.0.0.0:45662 0.0.0.0:* LISTEN - tcp 0 0 0.0.0.0:36385 0.0.0.0:* LISTEN 10316/java tcp 0 0 0.0.0.0:2049 0.0.0.0:* LISTEN - tcp 0 0 0.0.0.0:9090 0.0.0.0:* LISTEN 10316/java tcp 0 0 127.0.0.1:8005 0.0.0.0:* LISTEN 10316/java tcp 0 0 0.0.0.0:37029 0.0.0.0:* LISTEN 10316/java tcp 0 64 192.168.1.147:22 192.168.1.113:54267 ESTABLISHED 4269/sshd: felipe [ tcp 0 0 127.0.0.1:52772 127.0.0.1:3306 ESTABLISHED 10316/java tcp 0 0 127.0.0.1:52890 127.0.0.1:3306 ESTABLISHED 10316/java tcp 0 0 127.0.0.1:52774 127.0.0.1:3306 ESTABLISHED 10316/java tcp 0 0 127.0.0.1:52892 127.0.0.1:3306 ESTABLISHED 10316/java tcp 0 0 192.168.1.147:22 192.168.1.113:54020 ESTABLISHED 2803/sshd: felipe [ tcp 0 0 127.0.0.1:52886 127.0.0.1:3306 ESTABLISHED 10316/java tcp 0 0 127.0.0.1:52786 127.0.0.1:3306 ESTABLISHED 10316/java tcp 0 0 127.0.0.1:52884 127.0.0.1:3306 ESTABLISHED 10316/java tcp6 0 0 :::3306 :::* LISTEN 10111/mysqld tcp6 0 0 :::111 :::* LISTEN 1172/rpcbind tcp6 0 0 :::20048 :::* LISTEN 1237/rpc.mountd tcp6 0 0 :::22 :::* LISTEN 1157/sshd tcp6 0 0 :::39704 :::* LISTEN - tcp6 0 0 :::60640 :::* LISTEN 1168/rpc.statd tcp6 0 0 :::2049 :::* LISTEN - tcp6 0 0 127.0.0.1:3306 127.0.0.1:52890 ESTABLISHED 10111/mysqld tcp6 0 0 127.0.0.1:3306 127.0.0.1:52772 ESTABLISHED 10111/mysqld tcp6 0 0 127.0.0.1:3306 127.0.0.1:52892 ESTABLISHED 10111/mysqld tcp6 0 453 127.0.0.1:3306 127.0.0.1:52774 ESTABLISHED 10111/mysqld tcp6 0 0 127.0.0.1:3306 127.0.0.1:52884 ESTABLISHED 10111/mysqld tcp6 0 0 127.0.0.1:3306 127.0.0.1:52886 ESTABLISHED 10111/mysqld tcp6 0 0 127.0.0.1:3306 127.0.0.1:52786 ESTABLISHED 10111/mysqld udp 0 0 0.0.0.0:20048 0.0.0.0:* 1237/rpc.mountd udp 0 0 0.0.0.0:44766 0.0.0.0:* 956/dhclient udp 0 0 0.0.0.0:40682 0.0.0.0:* 10316/java udp 0 0 0.0.0.0:57148 0.0.0.0:* - udp 0 0 0.0.0.0:2049 0.0.0.0:* - udp 0 0 192.168.122.1:53 0.0.0.0:* 2073/dnsmasq udp 0 0 0.0.0.0:67 0.0.0.0:* 2073/dnsmasq udp 0 0 0.0.0.0:68 0.0.0.0:* 956/dhclient udp 0 0 0.0.0.0:111 0.0.0.0:* 1172/rpcbind udp 0 0 0.0.0.0:4446 0.0.0.0:* 10316/java udp 0 0 0.0.0.0:4446 0.0.0.0:* 10316/java udp 0 0 0.0.0.0:39791 0.0.0.0:* 1168/rpc.statd udp 0 0 0.0.0.0:917 0.0.0.0:* 1172/rpcbind udp 0 0 127.0.0.1:920 0.0.0.0:* 1168/rpc.statd udp6 0 0 :::20048 :::* 1237/rpc.mountd udp6 0 0 :::38744 :::* 1168/rpc.statd udp6 0 0 :::2049 :::* - udp6 0 0 :::111 :::* 1172/rpcbind udp6 0 0 :::55463 :::* 956/dhclient udp6 0 0 :::35028 :::* - udp6 0 0 :::917 :::* 1172/rpcbind The IPs are: 192.168.1.147 MANAGEMENT 192.168.1.140 host Here are my logs from management where it fails: 2016-12-11 19:24:32,887 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-111:ctx-0f9761e6) (logid:61cc1e9a) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to OvmDiscoverer 2016-12-11 19:24:32,887 DEBUG [c.c.r.ResourceManagerImpl] (AgentConnectTaskPool-111:ctx-0f9761e6) (logid:61cc1e9a) Dispatching resource state event CREATE_HOST_VO_FOR_CONNECTED to KvmServerDiscoverer 2016-12-11 19:24:32,892 DEBUG [c.c.u.d.T.Transaction] (AgentConnectTaskPool-111:ctx-0f9761e6) (logid:61cc1e9a) Rolling back the transaction: Time = 1 Name = AgentConnectTaskPool-111; called by -TransactionLegacy.rollback:879-TransactionLegacy.removeUpTo:822-TransactionLegacy.close:646-TransactionContextInterceptor.invoke:36-ReflectiveMethodInvocation.proceed:161-ExposeInvocationInterceptor.invoke:91-ReflectiveMethodInvocation.proceed:172-JdkDynamicAopProxy.invoke:204-$Proxy62.persist:-1-ResourceManagerImpl.createHostVO:1699-ResourceManagerImpl.createHostVOForConnectedAgent:1950-GeneratedMethodAccessor100.invoke:-1 2016-12-11 19:24:32,892 DEBUG [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-111:ctx-0f9761e6) (logid:61cc1e9a) Failed to handle host connection: com.cloud.utils.exception.CloudRuntimeException: DB Exception on: com.mysql.jdbc.JDBC4PreparedStatement@378d930f: INSERT INTO host (host.disconnected, host.name, host.status, host.type, host.private_ip_address, host.private_mac_address, host.private_netmask, host.public_netmask, host.public_ip_address, host.public_mac_address, host.storage_ip_address, host.cluster_id, host.storage_netmask, host.storage_mac_address, host.storage_ip_address_2, host.storage_netmask_2, host.storage_mac_address_2, host.hypervisor_type, host.proxy_port, host.resource, host.fs_type, host.available, host.setup, host.resource_state, host.hypervisor_version, host.update_count, host.uuid, host.data_center_id, host.pod_id, host.cpu_sockets, host.cpus, host.url, host.speed, host.ram, host.parent, host.guid, host.capabilities, host.total_size, host.last_ping, host.mgmt_server_id, host.dom0_memory, host.version, host.created) VALUES (null, _binary'server3', 'Creating', 'Routing', _binary'192.168.1.140', _binary'00:0c:29:13:3b:2a', _binary'255.255.255.0', null, null, null, _binary'192.168.1.140', 1, _binary'255.255.255.0', _binary'00:0c:29:13:3b:2a', null, null, null, 'KVM', null, null, null, 1, 0, 'Creating', null, 0, _binary'624c5f5a-4d30-42b8-98ce-9cf9f9593900', 1, 1, 2, 2, null, 2601, -49401856, null, _binary'4cff4b32-72bc-31d6-af43-c59ff0ca2711-LibvirtComputingResource', _binary'hvm,snapshot', null, 1446779563, 52237163884, 0, _binary'4.8.0', '2016-12-12 00:24:32') 2016-12-11 19:24:32,893 WARN [c.c.a.m.AgentManagerImpl] (AgentConnectTaskPool-111:ctx-0f9761e6) (logid:61cc1e9a) Unable to create attache for agent: Seq 0-0: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 1, [{"com.cloud.agent.api.StartupRoutingCommand":{"cpuSockets":2,"cpus":2,"speed":2601,"memory":-49401856,"dom0MinMemory":1073741824,"poolSync":false,"caps":"hvm,snapshot","pool":"/root","hypervisorType":"KVM","hostDetails":{"Host.OS.Kernel.Version":"3.10.0-327.36.3.el7.x86_64","com.cloud.network.Networks.RouterPrivateIpStrategy":"HostLocal","Host.OS.Version":"7.2.1511","Host.OS":"CentOS"},"hostTags":[],"groupDetails":{},"type":"Routing","dataCenter":"1","pod":"1","cluster":"1","guid":"4cff4b32-72bc-31d6-af43-c59ff0ca2711-LibvirtComputingResource","name":"server3","id":0,"version":"4.8.0","privateIpAddress":"192.168.1.140","privateMacAddress":"00:0c:29:13:3b:2a","privateNetmask":"255.255.255.0","storageIpAddress":"192.168.1.140","storageNetmask":"255.255.255.0","storageMacAddress":"00:0c:29:13:3b:2a","resourceName":"LibvirtComputingResource","gatewayIpAddress":"192.168.1.1","wait":0}},{"com.cloud.agent.api.StartupStorageCommand":{"totalSize":0,"poolInfo":{"uuid":"8616ce35-3d7f-4359-940d-6d8e481f934d","host":"192.168.1.140","localPath":"/var/lib/libvirt/images","hostPath":"/var/lib/libvirt/images","poolType":"Filesystem","capacityBytes":18746441728,"availableBytes":17023397888},"resourceType":"STORAGE_POOL","hostDetails":{},"type":"Storage","dataCenter":"1","pod":"1","guid":"4cff4b32-72bc-31d6-af43-c59ff0ca2711-LibvirtComputingResource","name":"server3","id":0,"version":"4.8.0","resourceName":"LibvirtComputingResource","wait":0}}] } 2016-12-11 19:24:32,977 WARN [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-13:null) (logid:) Throwing away a request because it came through as the first command on a connect: Seq 0--1: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 111, [{"com.cloud.agent.api.ShutdownCommand":{"reason":"sig.kill","wait":0}}] } 2016-12-11 19:24:32,977 WARN [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-14:null) (logid:) Throwing away a request because it came through as the first command on a connect: Seq 0-1: { Cmd , MgmtId: -1, via: 0, Ver: v1, Flags: 11, [{"com.cloud.agent.api.PingRoutingWithNwGroupsCommand":{"newGroupStates":{},"_hostVmStateReport":{},"_gatewayAccessible":true,"_vnetAccessible":true,"hostType":"Routing","hostId":0,"wait":0}}] } 2016-12-11 19:24:34,268 INFO [c.c.a.m.AgentManagerImpl] (AgentManager-Handler-15:null) (logid:) Connection from /192.168.1.140 closed but no cleanup was done. Here are the logs of the agent 2016-12-11 19:27:02,054 INFO [cloud.agent.AgentShell] (main:null) (logid:) Agent started 2016-12-11 19:27:02,056 INFO [cloud.agent.AgentShell] (main:null) (logid:) Implementation Version is 4.8.0 2016-12-11 19:27:02,057 INFO [cloud.agent.AgentShell] (main:null) (logid:) agent.properties found at /etc/cloudstack/agent/agent.properties 2016-12-11 19:27:02,061 INFO [cloud.agent.AgentShell] (main:null) (logid:) Defaulting to using properties file for storage 2016-12-11 19:27:02,062 INFO [cloud.agent.AgentShell] (main:null) (logid:) Defaulting to the constant time backoff algorithm 2016-12-11 19:27:02,075 INFO [cloud.utils.LogUtils] (main:null) (logid:) log4j configuration found at /etc/cloudstack/agent/log4j-cloud.xml 2016-12-11 19:27:02,087 INFO [cloud.agent.AgentShell] (main:null) (logid:) Preferring IPv4 address family for agent connection 2016-12-11 19:27:02,200 INFO [cloud.agent.Agent] (main:null) (logid:) id is 0 2016-12-11 19:27:02,202 WARN [cloud.resource.ServerResourceBase] (main:null) (logid:) Nics are not specified in properties file/db, will try to autodiscover 2016-12-11 19:27:02,207 INFO [cloud.resource.ServerResourceBase] (main:null) (logid:) Designating private to be nic eth0 2016-12-11 19:27:02,223 INFO [kvm.resource.LibvirtConnection] (main:null) (logid:) No existing libvirtd connection found. Opening a new one 2016-12-11 19:27:02,402 INFO [org.reflections.Reflections] (main:null) (logid:) Reflections took 35 ms to scan 1 urls, producing 7 keys and 10 values 2016-12-11 19:27:02,532 INFO [kvm.resource.LibvirtComputingResource] (main:null) (logid:) No libvirt.vif.driver specified. Defaults to BridgeVifDriver. 2016-12-11 19:27:02,551 INFO [cloud.agent.Agent] (main:null) (logid:) Agent [id = 0 : type = LibvirtComputingResource : zone = 1 : pod = 1 : workers = 5 : host = 192.168.1.147 : port = 8250 2016-12-11 19:27:02,554 INFO [utils.nio.NioClient] (main:null) (logid:) Connecting to 192.168.1.147:8250 2016-12-11 19:27:02,715 INFO [utils.nio.NioClient] (main:null) (logid:) SSL: Handshake done 2016-12-11 19:27:02,715 INFO [utils.nio.NioClient] (main:null) (logid:) Connected to 192.168.1.147:8250 2016-12-11 19:27:02,722 WARN [kvm.resource.LibvirtComputingResource] (Agent-Handler-1:null) (logid:) Could not read cpuinfo_max_freq 2016-12-11 19:27:02,762 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Attempting to create storage pool 8616ce35-3d7f-4359-940d-6d8e481f934d (Filesystem) in libvirt 2016-12-11 19:27:02,766 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Found existing defined storage pool 8616ce35-3d7f-4359-940d-6d8e481f934d, using it. 2016-12-11 19:27:02,766 INFO [kvm.storage.LibvirtStorageAdaptor] (Agent-Handler-1:null) (logid:) Trying to fetch storage pool 8616ce35-3d7f-4359-940d-6d8e481f934d from libvirt 2016-12-11 19:27:02,819 INFO [cloud.serializer.GsonHelper] (Agent-Handler-1:null) (logid:) Default Builder inited. 2016-12-11 19:27:02,848 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Proccess agent startup answer, agent id = 0 2016-12-11 19:27:02,849 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Set agent id 0 2016-12-11 19:27:02,856 INFO [cloud.agent.Agent] (Agent-Handler-2:null) (logid:) Startup Response Received: agent id = 0 2016-12-11 19:27:02,859 INFO [cloud.agent.Agent] (AgentShutdownThread:null) (logid:) Stopping the agent: Reason = sig.kill
