回复: VR deletes IP address by mistake

[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ć