You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cloudstack.apache.org by li jerry <di...@hotmail.com> on 2020/04/02 05:47:02 UTC
VR deletes IP address by mistake
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 cloud-password-server@10.40.59.251
2020-02-29 07:47:55,252 CsHelper.py service:225 Service cloud-password-server@10.40.59.251 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
回复: VR deletes IP address by mistake
Posted by li jerry <di...@hotmail.com>.
Andrija, thank you for your reply
I checked the content of / var / cache / cloud / processed / vm_dhcp_entry.json.c841db94-4a2e-4130-babe-6e8173dbebf4.gz, which is correct (delete the correct IP)
root@r-1247-VM:/var/cache/cloud/processed# zcat /var/cache/cloud/processed/vm_dhcp_entry.json.c841db94-4a2e-4130-babe-6e8173dbebf4.gz
{"host_name":"Test-AD01","mac_address":"1e:00:c1:00:04:51","ipv4_address":"10.40.59.35","ipv6_duid":"00:03:00:01:1e:00:c1:00:04:51","dns_addresses":"10.40.59.251","default_gateway":"10.40.59.1","default_entry":true,"remove":true,"type":"dhcpentry"}
/Var / cache / cloud / processed / in this directory
The file containing 10.40.59.143 information is Oct 11 08:54, which has been five months since then. So I ruled it out
-----邮件原件-----
发件人: Andrija Panic <an...@gmail.com>
发送时间: 2020年4月4日 4:28
收件人: users <us...@cloudstack.apache.org>
主题: Re: VR deletes IP address by mistake
Hi Li,
inside the VR for that VM - do:
zcat
/var/cache/cloud/processed/vm_dhcp_entry.json.c841db94-4a2e-4130-babe-6e8173dbebf4.gz
This contains the VM's DHCP entry which should be removed - you should be able to see the correct IP there (10.40.59.35) or the wrong one.
I find it "funny" that the 10.40.59.35 (correct one) doesn't seem visible in cloud.log (and if this is the case, I would expect that JSON to contain the wrong IP, not the correct one)
What is readable is "Attempting to delete entries from dnsmasq.leases file for VMs which are not on dhcphosts file" - in that sense - it means that the 10.40.59.143 (wrong IP) was at some moment removed from the /etc/dhcphosts.txt.
Confirm that JSON content, and also try to grep for the wrong IP
10.40.59.143 in the cloud.log (or any older cloud.log.gz if there are any)
- there should be some traces of that IP somewhere in the logs. Also try zgrep against /var/cache/cloud/processed/vm_dhcp_entry.json* files - should be there somewhere visible - as this IP is somehow returned as the variable/input to the CsDhcp.py script.
Best
Andrija
On Thu, 2 Apr 2020 at 07:47, li jerry <di...@hotmail.com> wrote:
> 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 cloud-password-server@10.40.59.251
> 2020-02-29 07:47:55,252 CsHelper.py service:225 Service
> cloud-password-server@10.40.59.251 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
>
>
--
Andrija Panić
Re: VR deletes IP address by mistake
Posted by Andrija Panic <an...@gmail.com>.
Hi Li,
inside the VR for that VM - do:
zcat
/var/cache/cloud/processed/vm_dhcp_entry.json.c841db94-4a2e-4130-babe-6e8173dbebf4.gz
This contains the VM's DHCP entry which should be removed - you should be
able to see the correct IP there (10.40.59.35) or the wrong one.
I find it "funny" that the 10.40.59.35 (correct one) doesn't seem visible
in cloud.log (and if this is the case, I would expect that JSON to contain
the wrong IP, not the correct one)
What is readable is "Attempting to delete entries from dnsmasq.leases file
for VMs which are not on dhcphosts file" - in that sense - it means that
the 10.40.59.143 (wrong IP) was at some moment removed from the
/etc/dhcphosts.txt.
Confirm that JSON content, and also try to grep for the wrong IP
10.40.59.143 in the cloud.log (or any older cloud.log.gz if there are any)
- there should be some traces of that IP somewhere in the logs. Also try
zgrep against /var/cache/cloud/processed/vm_dhcp_entry.json* files -
should be there somewhere visible - as this IP is somehow returned as the
variable/input to the CsDhcp.py script.
Best
Andrija
On Thu, 2 Apr 2020 at 07:47, li jerry <di...@hotmail.com> wrote:
> 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 cloud-password-server@10.40.59.251
> 2020-02-29 07:47:55,252 CsHelper.py service:225 Service
> cloud-password-server@10.40.59.251 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
>
>
--
Andrija Panić