Hello All
Recently, we found that VM IP lost in share network. Further analysis of the
log shows that when VM is deleted, the IP address is deleted incorrectly.I
can't reproduce this fault, but I've had two such incidents.
Have you ever had such a situation, how to check it or is it a known bug?
cloudstack: 4.13.0
Here are the logs on management and VR (time difference between management and
VR + 8)
The IP address that should be deleted is: 10.40.59.35
The IP address actually deleted by VR is: 10.40.59.143
That's the problem.
Management.log
2020-02-29 15:47:50,691 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-88:ctx-3177c6e5 job-168703 ctx-539ad775) (logid:5de4a319)
Destroying vm VM[User|i-31-4604-VM]
2020-02-29 15:47:50,691 DEBUG [c.c.v.VirtualMachineManagerImpl]
(API-Job-Executor-88:ctx-3177c6e5 job-168703 ctx-539ad775) (logid:5de4a319)
Cleaning up NICS
2020-02-29 15:47:50,691 DEBUG [o.a.c.e.o.NetworkOrchestrator]
(API-Job-Executor-88:ctx-3177c6e5 job-168703 ctx-539ad775) (logid:5de4a319)
Cleaning network for vm: 4604
2020-02-29 15:47:50,703 DEBUG [o.a.c.n.t.AdvancedNetworkTopology]
(API-Job-Executor-88:ctx-3177c6e5 job-168703 ctx-539ad775) (logid:5de4a319)
REMOVE VPC DHCP ENTRY RULES
2020-02-29 15:47:50,704 DEBUG [o.a.c.n.t.BasicNetworkTopology]
(API-Job-Executor-88:ctx-3177c6e5 job-168703 ctx-539ad775) (logid:5de4a319)
Applying dhcp entry in network Ntwk[264|Guest|13]
2020-02-29 15:47:50,726 DEBUG [c.c.a.t.Request]
(API-Job-Executor-88:ctx-3177c6e5 job-168703 ctx-539ad775) (logid:5de4a319) Seq
17-4102497785557818386: Sending { Cmd , MgmtId: 240661250348494, via:
17(wxac6005), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"1e:00:c1:00:04:51","vmIpAddress":"10.40.59.35","vmName":"Test-AD01","defaultRouter":"10.40.59.1","defaultDns":"10.40.59.251","duid":"00:03:00:01:1e:00:c1:00:04:51","isDefault":true,"executeInSequence":false,"remove":true,"accessDetails":{"router.name":"r-1247-VM","router.guest.ip":"10.40.59.251","router.ip":"169.254.2.248","zone.network.type":"Advanced"},"wait":0}}]
}
2020-02-29 15:47:50,726 DEBUG [c.c.a.t.Request]
(API-Job-Executor-88:ctx-3177c6e5 job-168703 ctx-539ad775) (logid:5de4a319) Seq
17-4102497785557818386: Executing: { Cmd , MgmtId: 240661250348494, via:
17(wxac6005), Ver: v1, Flags: 100011,
[{"com.cloud.agent.api.routing.DhcpEntryCommand":{"vmMac":"1e:00:c1:00:04:51","vmIpAddress":"10.40.59.35","vmName":"Test-AD01","defaultRouter":"10.40.59.1","defaultDns":"10.40.59.251","duid":"00:03:00:01:1e:00:c1:00:04:51","isDefault":true,"executeInSequence":false,"remove":true,"accessDetails":{"router.name":"r-1247-VM","router.guest.ip":"10.40.59.251","router.ip":"169.254.2.248","zone.network.type":"Advanced"},"wait":0}}]
}
2020-02-29 15:47:50,726 DEBUG [c.c.a.m.DirectAgentAttache]
(DirectAgent-426:ctx-eb96586b) (logid:c53c10cb) Seq 17-4102497785557818386:
Executing request
2020-02-29 15:47:50,726 DEBUG [c.c.a.r.v.VirtualRoutingResource]
(DirectAgent-426:ctx-eb96586b) (logid:5de4a319) Transforming
com.cloud.agent.api.routing.DhcpEntryCommand to ConfigItems
2020-02-29 15:47:50,726 DEBUG [c.c.a.r.v.f.AbstractConfigItemFacade]
(DirectAgent-426:ctx-eb96586b) (logid:5de4a319) Transformed filename:
vm_dhcp_entry.json to: vm_dhcp_entry.json.c841db94-4a2e-4130-babe-6e8173dbebf4
2020-02-29 15:47:51,053 DEBUG [c.c.h.x.r.CitrixResourceBase]
(DirectAgent-426:ctx-eb96586b) (logid:5de4a319) Copying VR with ip
169.254.2.248 config file into host 10.40.38.248
Vr cloud.log
2020-02-29 07:47:54,992 update_config.py <module>:146 update_config.py ::
Processing incoming file =>
vm_dhcp_entry.json.c841db94-4a2e-4130-babe-6e8173dbebf4
2020-02-29 07:47:54,992 update_config.py process_file:50 Processing JSON file
vm_dhcp_entry.json.c841db94-4a2e-4130-babe-6e8173dbebf4
2020-02-29 07:47:54,992 merge.py load:296 Continuing with the processing of
file '/var/cache/cloud/vm_dhcp_entry.json.c841db94-4a2e-4130-babe-6e8173dbebf4'
2020-02-29 07:47:54,996 merge.py process:101 Command of type dhcpentry received
2020-02-29 07:47:55,004 CsHelper.py execute:188 Executing: ip addr show dev
eth1
2020-02-29 07:47:55,023 CsHelper.py execute:188 Executing: ip addr show dev
eth0
2020-02-29 07:47:55,042 CsHelper.py execute:188 Executing: ip addr show dev
eth1
2020-02-29 07:47:55,061 CsAddress.py process:108 Address found in DataBag ==>
{u'public_ip': u'169.254.2.248', u'one_to_one_nat': False, u'nic_dev_id': u'1',
u'network': u'169.254.0.0/16', u'netmask': u'255.255.0.0', u'source_nat':
False, u'broadcast': u'169.254.255.255', u'add': True, u'nw_type': u'control',
u'device': u'eth1', u'cidr': u'169.254.2.248/16', u'gateway': u'', u'size':
u'16'}
2020-02-29 07:47:55,061 CsAddress.py process:116 Address 169.254.2.248/16 on
device eth1 already configured
2020-02-29 07:47:55,062 CsRoute.py defaultroute_exists:115 Checking if default
ipv4 route is present
2020-02-29 07:47:55,062 CsHelper.py execute:188 Executing: ip -4 route list 0/0
2020-02-29 07:47:55,080 CsRoute.py defaultroute_exists:119 Default route
found: default via 10.40.59.1 dev eth0
2020-02-29 07:47:55,081 CsHelper.py execute:188 Executing: ip addr show dev
eth0
2020-02-29 07:47:55,100 CsAddress.py process:108 Address found in DataBag ==>
{u'public_ip': u'10.40.59.251', u'one_to_one_nat': False, u'nic_dev_id': u'0',
u'network': u'10.40.59.0/24', u'netmask': u'255.255.255.0', u'source_nat':
False, u'broadcast': u'10.40.59.255', u'add': True, u'nw_type': u'guest',
u'device': u'eth0', u'cidr': u'10.40.59.251/24', u'gateway': u'', u'size':
u'24'}
2020-02-29 07:47:55,101 CsAddress.py process:116 Address 10.40.59.251/24 on
device eth0 already configured
2020-02-29 07:47:55,101 CsRoute.py add_table:37 Adding route table: 100
Table_eth0 to /etc/iproute2/rt_tables if not present
2020-02-29 07:47:55,102 CsHelper.py execute:188 Executing: ip rule show
2020-02-29 07:47:55,118 CsHelper.py execute:188 Executing: ip rule show
2020-02-29 07:47:55,136 CsHelper.py execute:188 Executing: ip link show eth0 |
grep 'state DOWN'
2020-02-29 07:47:55,154 CsHelper.py execute:193 Command 'ip link show eth0 |
grep 'state DOWN'' returned non-zero exit status 1
2020-02-29 07:47:55,167 CsRoute.py add_network_route:73 Adding route: dev eth0
table: Table_eth0 network: 10.40.59.0/24 if not present
2020-02-29 07:47:55,168 CsHelper.py execute:188 Executing: ip route show type
throw 10.40.59.0/24 table Table_eth0 proto static
2020-02-29 07:47:55,186 CsHelper.py execute:188 Executing: sudo ip route flush
cache
2020-02-29 07:47:55,226 CsHelper.py execute:188 Executing: systemctl start
[email protected]
2020-02-29 07:47:55,252 CsHelper.py service:225 Service
[email protected] start
2020-02-29 07:47:55,253 CsRoute.py defaultroute_exists:115 Checking if default
ipv4 route is present
2020-02-29 07:47:55,253 CsHelper.py execute:188 Executing: ip -4 route list 0/0
2020-02-29 07:47:55,269 CsRoute.py defaultroute_exists:119 Default route
found: default via 10.40.59.1 dev eth0
2020-02-29 07:47:55,288 CsHelper.py execute:188 Executing: ip addr show
2020-02-29 07:47:55,320 CsFile.py commit:60 Nothing to commit. The
/etc/dnsmasq.d/cloud.conf file did not change
2020-02-29 07:47:55,320 CsFile.py commit:66 Wrote edited file
/etc/dhcphosts.txt
2020-02-29 07:47:55,321 CsFile.py commit:68 Updated file in-cache configuration
2020-02-29 07:47:55,321 CsFile.py commit:60 Nothing to commit. The
/etc/dhcpopts.txt file did not change
2020-02-29 07:47:55,321 CsDhcp.py delete_leases:122 Attempting to delete
entries from dnsmasq.leases file for VMs which are not on dhcphosts file
2020-02-29 07:47:55,321 CsDhcp.py delete_leases:133 dhcp_release $(ip route
get 10.40.59.143 | grep eth | head -1 | awk '{print $3}') 10.40.59.143
1e:00:86:00:04:bd
2020-02-29 07:47:55,321 CsHelper.py execute:188 Executing: dhcp_release $(ip
route get 10.40.59.143 | grep eth | head -1 | awk '{print $3}') 10.40.59.143
1e:00:86:00:04:bd
2020-02-29 07:47:55,348 CsDhcp.py delete_leases:137 Deleted 1 entries from
dnsmasq.leases file
2020-02-29 07:47:55,355 CsFile.py commit:66 Wrote edited file /etc/hosts
2020-02-29 07:47:55,355 CsFile.py commit:68 Updated file in-cache configuration
2020-02-29 07:47:55,355 CsDhcp.py write_hosts:156 Updated hosts file
2020-02-29 07:47:55,355 CsHelper.py execute:188 Executing: systemctl restart
dnsmasq
2020-02-29 07:47:55,614 CsHelper.py service:225 Service dnsmasq restart
2020-02-29 07:47:55,615 CsHelper.py execute:188 Executing: systemctl stop
conntrackd
2020-02-29 07:47:55,641 CsHelper.py service:225 Service conntrackd stop
2020-02-29 07:47:55,642 CsHelper.py execute:188 Executing: systemctl stop
keepalived
2020-02-29 07:47:55,668 CsHelper.py service:225 Service keepalived stop
2020-02-29 07:47:55,668 CsHelper.py execute:188 Executing: mount
-Jerry
