Automatic OS IP assignment. What do I need to make this happen?

Great work @TomK!!! Thanks for sharing this with the community.

Best,
Álex.

@ahuertas, @atodorov_storpool,

I’m adapting the driver to OpenNebula 5.10.1. When I try to use it as-is, I see that ON 5.10.1 just passes a 5 to the IPAM driver. From our earlier conversations, I’m getting the impression that I won’t need to decrypt anything. However appears ON 5.10.1 introduced additional changes since only a ‘5’ is passed to the get_address function:

==> /var/log/one/oned.log <==
Sat May 30 23:04:05 2020 [Z0][AuM][D]: Message received: AUTHENTICATE SUCCESS 4 -

Sat May 30 23:04:05 2020 [Z0][ReM][D]: Req:5008 UID:0 IP:127.0.0.1 one.template.info invoked , 3, false, false
Sat May 30 23:04:05 2020 [Z0][ReM][D]: Req:5008 UID:0 one.template.info result SUCCESS, "<VMTEMPLATE><ID>3</I..."
Sat May 30 23:04:05 2020 [Z0][ReM][D]: Req:2976 UID:0 IP:127.0.0.1 one.template.instantiate invoked , 3, "getautonet05.nix.mds...", false, "DISK=[
  FORMAT="raw...", false
Sat May 30 23:04:05 2020 [Z0][IPM][D]: Message received: LOG I 5 Command execution failed (exit code: 1): /var/lib/one/remotes/ipam/GetAutoNet/get_address 5

Sat May 30 23:04:05 2020 [Z0][IPM][I]: Command execution failed (exit code: 1): /var/lib/one/remotes/ipam/GetAutoNet/get_address 5
Sat May 30 23:04:05 2020 [Z0][IPM][D]: Message received: GET_ADDRESS FAILURE 5 LQ==

Sat May 30 23:04:05 2020 [Z0][IPM][E]: LQ==
Sat May 30 23:04:05 2020 [Z0][ONE][E]: Cannot get IP/MAC lease from virtual network 26.
Sat May 30 23:04:05 2020 [Z0][ReM][E]: Req:2976 UID:0 one.template.instantiate result FAILURE [one.template.instantiate] Error allocating a new virtual machine template. Cannot get IP/MAC lease from virtual network 26.

==> /var/log/one/sunstone.log <==
Sat May 30 23:04:05 2020 [I]: 192.168.0.76 - - [30/May/2020:23:04:05 -0400] "POST /vmtemplate/3/action HTTP/1.1" 500 - 0.8558

==> /var/log/one/oned.log <==
Sat May 30 23:04:16 2020 [Z0][InM][D]: Host mdskvm-p05.nix.mds.xyz (4) successfully monitored.
Sat May 30 23:04:16 2020 [Z0][VMM][D]: VM 45 successfully monitored: STATE=a CPU=1.0 MEMORY=647720 NETRX=259533 NETTX=20915 DISKRDBYTES=218926668 DISKWRBYTES=8906240 DISKRDIOPS=64152 DISKWRIOPS=222
Sat May 30 23:04:17 2020 [Z0][VMM][D]: VM 50 successfully monitored: STATE=a CPU=0.0 MEMORY=668876 NETRX=256587 NETTX=19649 DISKRDBYTES=215367244 DISKWRBYTES=8658944 DISKRDIOPS=63988 DISKWRIOPS=200
Sat May 30 23:04:23 2020 [Z0][ReM][D]: Req:16 UID:0 IP:127.0.0.1 one.zone.raftstatus invoked
Sat May 30 23:04:23 2020 [Z0][ReM][D]: Req:16 UID:0 one.zone.raftstatus result SUCCESS, "<RAFT><SERVER_ID>-1<..."
Sat May 30 23:04:23 2020 [Z0][ReM][D]: Req:6768 UID:0 IP:127.0.0.1 one.vmpool.infoextended invoked , -2, -1, -1, -1
Sat May 30 23:04:23 2020 [Z0][ReM][D]: Req:6768 UID:0 one.vmpool.infoextended result SUCCESS, "<VM_POOL><VM><ID>50<..."
Sat May 30 23:04:23 2020 [Z0][ReM][D]: Req:4832 UID:0 IP:127.0.0.1 one.vmpool.infoextended invoked , -2, -1, -1, -1
Sat May 30 23:04:23 2020 [Z0][ReM][D]: Req:4832 UID:0 one.vmpool.infoextended result SUCCESS, "<VM_POOL><VM><ID>50<..."
^C
[root@one01 ipam]#
[root@one01 ipam]#
[root@one01 ipam]# /var/lib/one/remotes/ipam/GetAutoNet/get_address 5
[root@one01 ipam]# echo $?
1
[root@one01 ipam]# ls -altri /var/lib/one/remotes/ipam/GetAutoNet/
total 56
135154756 -rw-r-----. 1 oneadmin oneadmin   546 Mar 15 14:22 register-address-range.xml
135154749 -rw-r-----. 1 oneadmin oneadmin   644 Mar 16 01:09 allocate-address-range.xml
135154755 -rw-r-----. 1 oneadmin oneadmin   546 Mar 16 01:55 get-single-address.xml
135154753 -rw-r-----. 1 oneadmin oneadmin   644 Mar 16 01:57 free-address-range.xml
135154754 -rw-r-----. 1 oneadmin oneadmin   585 Mar 16 02:01 get-address-range.xml
135154748 -rwxr-x---. 1 oneadmin oneadmin 32282 Mar 28 18:39 GetAutoNet.py
135154757 lrwxrwxrwx. 1 oneadmin oneadmin    13 May 30 23:02 get_single -> GetAutoNet.py
135154758 lrwxrwxrwx. 1 oneadmin oneadmin    13 May 30 23:02 free_address -> GetAutoNet.py
135154759 lrwxrwxrwx. 1 oneadmin oneadmin    13 May 30 23:02 get_address -> GetAutoNet.py
135154760 lrwxrwxrwx. 1 oneadmin oneadmin    13 May 30 23:02 allocate_address -> GetAutoNet.py
135154761 lrwxrwxrwx. 1 oneadmin oneadmin    13 May 30 23:02 unregister_address_range -> GetAutoNet.py
135154762 lrwxrwxrwx. 1 oneadmin oneadmin    13 May 30 23:02 register_address_range -> GetAutoNet.py
135154747 drwxr-x---. 2 oneadmin oneadmin  4096 May 30 23:02 .
134569729 drwxr-x---. 6 oneadmin oneadmin    69 May 30 23:02 ..
[root@one01 ipam]# tail -f /var/log/GetAutoNet/GetAutoNet.log
isBase64(self,sb):
ERROR: sys.argv[1] is neither a file, base64 encoded string nor a plain readable file.  Exiting.

getAddress(self):
isBase64(self,sb):
self.isBase64(): False
isBase64(self,sb):
isBase64(self,sb):
ERROR: sys.argv[1] is neither a file, base64 encoded string nor a plain readable file.  Exiting.

Could you please shed more light on what should I expect as input to the IPAM driver from ON 5.10.1 ?

Cheers,
TK

Hello @TomK

First of all, sorry for the delay in my answer.

As we were talking, there was a change in the encryption process, but the IPAM driver gets the data unencrypted, so you don’t have to make any decryption operation. For example, if we check src/ipamm_mad/remotes/packet/get_address:

data = Nokogiri::XML(Base64.decode64(STDIN.read))

It just reads the STDIN and parses it to XML.

Could you please paste here the VM template (onetemplate show TEMPLATE_ID -x) you are trying to instantiate? I would like to check that everything is correct.

Best,
Álex.

Hey Alex,

No worries. Got tied up with a few other things myself as well.

Yep. I recalled our discussion above. So what I was thinking would happen is that instead of passing a base64 string:

[oneadmin@one01 GetAutoNet]$ ./get_single  PElQQU1fRFJJVkVSX0FDVElPTl9EQVRBPgo8QVI+CiAgPFRZUEU+SVA0PC9UWVBFPgogIDxJUD4xMC4wLjAuMTwvSVA+CiAgPE1BQz5BQTpCQjpDQzpERDowMDowMTwvTUFDPgogIDxTSVpFPjI1NTwvU0laRT4KICA8TkVUV09SS19BRERSRVNTPjEwLjAuMC4xMTc8L05FVFdPUktfQUREUkVTUz4KICA8TkVUV09SS19NQVNLPjI1NS4yNTUuMjU1LjA8L05FVFdPUktfTUFTSz4KICA8R0FURVdBWT4xMC4wLjAuMTwvR0FURVdBWT4KICA8RE5TPjE5Mi4xNjguMC40NCAxOTIuMTY4LjAuNDUgMTkyLjE2OC4wLjE1NCAxOTIuMTY4LjAuMTU1IDE5Mi4xNjguMC4yMjQgMTkyLjE2OC4wLjIyMCAxOTIuMTY4LjAuMjIxPC9ETlM+CiAgPEdVRVNUX01UVT4xNTAwPC9HVUVTVF9NVFU+CiAgPFNFQVJDSF9ET01BSU4+bXdzLm1kcy54eXogbml4Lm1kcy54eXogbWRzLnh5ejwvU0VBUkNIX0RPTUFJTj4KICA8TE9XRVJfTElNSVQ+MTAwPC9MT1dFUl9MSU1JVD4KICA8VVBQRVJfTElNSVQ+MjU1PC9VUFBFUl9MSU1JVD4KPC9BUj4KPC9JUEFNX0RSSVZFUl9BQ1RJT05fREFUQT4K

            AR = [
                IP  = "10.0.0.100",
                SIZE = "1"
            ]

[oneadmin@one01 GetAutoNet]$

The 5.10.1 ON would instead require just the non-base64 text as input or similar, such as this:

[oneadmin@one01 GetAutoNet]$ ./get_single  "<IPAM_DRIVER_ACTION_DATA>
<AR>
  <TYPE>IP4</TYPE>
  <IP>10.0.0.1</IP>
  <MAC>AA:BB:CC:DD:00:01</MAC>
  <SIZE>255</SIZE>
  <NETWORK_ADDRESS>10.0.0.117</NETWORK_ADDRESS>
  <NETWORK_MASK>255.255.255.0</NETWORK_MASK>
  <GATEWAY>10.0.0.1</GATEWAY>
  <DNS>192.168.0.44 192.168.0.45 192.168.0.154 192.168.0.155 192.168.0.224 192.168.0.220 192.168.0.221</DNS>
  <GUEST_MTU>1500</GUEST_MTU>
  <SEARCH_DOMAIN>mws.mds.xyz nix.mds.xyz mds.xyz</SEARCH_DOMAIN>
  <LOWER_LIMIT>100</LOWER_LIMIT>
  <UPPER_LIMIT>255</UPPER_LIMIT>
</AR>
</IPAM_DRIVER_ACTION_DATA>"

                AR = [
                    IP  = "10.0.0.100",
                    SIZE = "1"
                ]

[oneadmin@one01 GetAutoNet]$

But instead I saw that just a number ‘5’ is entered as the parameter. So wasn’t sure what to think of it:

Sat May 30 23:04:05 2020 [Z0][IPM][D]: Message received: LOG I 5 Command execution failed (exit code: 1): **/var/lib/one/remotes/ipam/GetAutoNet/get_address 5**

Including output of the onetemplate command below:

[oneadmin@one01 ~]$ onetemplate show 3 -x
<VMTEMPLATE>
  <ID>3</ID>
  <UID>0</UID>
  <GID>0</GID>
  <UNAME>oneadmin</UNAME>
  <GNAME>oneadmin</GNAME>
  <NAME>CentOS 7 - Template - Kickstart - Context - GV 0</NAME>
  <PERMISSIONS>
    <OWNER_U>1</OWNER_U>
    <OWNER_M>1</OWNER_M>
    <OWNER_A>0</OWNER_A>
    <GROUP_U>0</GROUP_U>
    <GROUP_M>0</GROUP_M>
    <GROUP_A>0</GROUP_A>
    <OTHER_U>0</OTHER_U>
    <OTHER_M>0</OTHER_M>
    <OTHER_A>0</OTHER_A>
  </PERMISSIONS>
  <REGTIME>1584507109</REGTIME>
  <TEMPLATE>
    <CONTEXT>
      <NETWORK><![CDATA[YES]]></NETWORK>
      <REPORT_READY><![CDATA[YES]]></REPORT_READY>
      <SSH_PUBLIC_KEY><![CDATA[ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC8QYRv9NV9Kdw7KINeeGTHywr4AhOwy69szGKDrsHtcIqTqfJkWU0ysUFTv9SldFCroebyYSz1wgzAxEsQMQSyLhuP4PPvUXa6rHRH7F/YuTsTWZZH6xaQi98Hucsl5sGm5dJ/+mej7yiHDIFhSmN9N1rEYxH8nyWsZjdzz6coqUm/aYqTjfxk7o4ekwAnRSb5oiS7qgvieXFPr7vgELFIUjkw2DR1Wl1zLwnKD6NK5BGa/BBCRcBMkXvQmjVy6ILtxdS/PFvkMMF/Zus5wkHy2F/vLGcpYN2IkPzv8C8ihL6mqFAaydSeK7T2J81crQP7VDKbzHnSPistk8bMFCap root@awx01.nix.mds.xyz]]></SSH_PUBLIC_KEY>
      <START_SCRIPT_BASE64><![CDATA[IyEvYmluL2Jhc2gKCiMgQ2hlY2sgaWYgbmV0d29yayBpcyByZWFjaGFibGUuIElmIG5vdCwgdHJ5IHRvIGdldCBvbiB0aGUgbmV0d29yay4KcGluZyBnb29nbGUuY29tIC1jNHxncmVwICIxMDAlIHBhY2tldCBsb3NzIiA+IC9kZXYvbnVsbDsKUkVUVlY9JD8KW1sgJFJFVFZWID09IDAgXV0gJiYgewogICAgICAgIGVjaG8gIkNhbid0IHJlYWNoIGdvb2dsZS5jb20uICBSdW5uaW5nIGRoY2xpZW50IC4uLiI7CiAgICAgICAgZGhjbGllbnQKfQoKeXVtIGluc3RhbGwgd2dldCAteQp5dW0gaW5zdGFsbCBodHRwczovL2dpdGh1Yi5jb20vT3Blbk5lYnVsYS9hZGRvbi1jb250ZXh0LWxpbnV4L3JlbGVhc2VzL2Rvd25sb2FkL3Y1LjguMC9vbmUtY29udGV4dC01LjguMC0xLmVsNy5ub2FyY2gucnBtIC15CgojIEVuYWJsZSB0aGUgc2VydmljZSwgaWYgbm90IGFscmVhZHkuICBEb2Vzbid0IGh1cnQgdG8gbWFrZSBzdXJlLgpzeXN0ZW1jdGwgZW5hYmxlIG9uZS1jb250ZXh0CgojIFRoaXMgaXMgc3VwcG9zZWQgdG8gaGFwcGVuIG9uY2UgYWZ0ZXIgcHJvdmlzaW9uaW5nLgpvbmVnYXRlIHZtIHNob3cKUkVUVj0kPwoKCiMgVHJ5IG51bWVyb3VzIHRpbWVzIHRvIHJlYWNoIGEgcmVtb3RlIHNpdGUuICBJZiBzdGlsbCBmYWlsZWQsIHRoZW4gcmVzdGFydC4KZm9yIFZBTCBpbiB7MS4uNn07IGRvCiAgICAgICAgZWNobyAiVHJ5aW5nIHRvIHBpbmcgZ29vZ2xlLmNvbSAkVkFMIC4uLiI7CiAgICAgICAgcGluZyAxOTIuMTY4LjAuMSAtYzR8Z3JlcCAiMCUgcGFja2V0IGxvc3MiID4gL2Rldi9udWxsOwogICAgICAgIFJFVFZWPSQ/CiAgICAgICAgc2xlZXAgMTA7CiAgICAgICAgW1sgJFJFVFZWID09IDAgXV0gJiYgewogICAgICAgICAgICAgICAgYnJlYWs7CiAgICAgICAgfQpkb25lCgpbWyAkUkVUViAhPSAwICYmICRSRVRWViAhPSAwICYmICQocnBtIC1hcXxncmVwIC1FaSBvbmUtY29udGV4dCkgIT0gIiIgXV0gJiYgewogICAgICAgIGVjaG8gIlJlc3RhcnRpbmcgYWZ0ZXIgaW5zdGFsbGluZyBvbmUtY29udGV4dC4gIFRoaXMgd2lsbCBzZXQgdGhlIElQIG9uIHRoaXMgVk0gdGhhdCdzIGJlZW4gYWxsb2NhdGVkIGluIHRoZSBVSS4iIHwgdGVlIC1hIC92YXIvbG9nL21lc3NhZ2VzOwogICAgICAgIGVjaG8gIlJFQk9PVCEiIHwgdGVlIC1hIC92YXIvbG9nL21lc3NhZ2VzOwogICAgICAgIHJlYm9vdDsKfQoK]]></START_SCRIPT_BASE64>
      <TOKEN><![CDATA[YES]]></TOKEN>
    </CONTEXT>
    <CPU><![CDATA[2]]></CPU>
    <DESCRIPTION><![CDATA[rhel7-template]]></DESCRIPTION>
    <DISK>
      <FORMAT><![CDATA[raw]]></FORMAT>
      <SIZE><![CDATA[65536]]></SIZE>
      <TYPE><![CDATA[fs]]></TYPE>
    </DISK>
    <DISK>
      <IMAGE><![CDATA[CentOS-7-x86_64-Minimal-1908-Kickstart-Context - GV - IMG 0 - V 28]]></IMAGE>
      <IMAGE_UNAME><![CDATA[oneadmin]]></IMAGE_UNAME>
    </DISK>
    <GRAPHICS>
      <LISTEN><![CDATA[0.0.0.0]]></LISTEN>
      <TYPE><![CDATA[VNC]]></TYPE>
    </GRAPHICS>
    <HYPERVISOR><![CDATA[kvm]]></HYPERVISOR>
    <INPUTS_ORDER><![CDATA[]]></INPUTS_ORDER>
    <LOGO><![CDATA[images/logos/centos.png]]></LOGO>
    <MEMORY><![CDATA[4096]]></MEMORY>
    <MEMORY_COST><![CDATA[5]]></MEMORY_COST>
    <MEMORY_UNIT_COST><![CDATA[MB]]></MEMORY_UNIT_COST>
    <NIC>
      <NETWORK><![CDATA[IPAM - onevnet02 - VLAN 2 - 10.0.0.X]]></NETWORK>
      <NETWORK_UNAME><![CDATA[oneadmin]]></NETWORK_UNAME>
      <SECURITY_GROUPS><![CDATA[0]]></SECURITY_GROUPS>
    </NIC>
    <OS>
      <ARCH><![CDATA[x86_64]]></ARCH>
      <BOOT><![CDATA[disk0,nic0,disk1]]></BOOT>
    </OS>
    <SCHED_DS_REQUIREMENTS><![CDATA[ID="129"]]></SCHED_DS_REQUIREMENTS>
    <SCHED_REQUIREMENTS><![CDATA[ID="5" | CLUSTER_ID="100"]]></SCHED_REQUIREMENTS>
    <VCPU><![CDATA[2]]></VCPU>
  </TEMPLATE>
</VMTEMPLATE>
[oneadmin@one01 ~]$

Cheers,
TK

Hello @TomK

I need the output of onevnet show "IPAM - onevnet02 - VLAN 2 - 10.0.0.X" -x so I can check all the parameters in the virtual network.

Best,
Álex.

Here you go:

[oneadmin@one01 ~]$ onevnet show "IPAM - onevnet02 - VLAN 2 - 10.0.0.X" -x
<VNET>
  <ID>26</ID>
  <UID>0</UID>
  <GID>0</GID>
  <UNAME>oneadmin</UNAME>
  <GNAME>oneadmin</GNAME>
  <NAME>IPAM - onevnet02 - VLAN 2 - 10.0.0.X</NAME>
  <PERMISSIONS>
    <OWNER_U>1</OWNER_U>
    <OWNER_M>1</OWNER_M>
    <OWNER_A>0</OWNER_A>
    <GROUP_U>0</GROUP_U>
    <GROUP_M>0</GROUP_M>
    <GROUP_A>0</GROUP_A>
    <OTHER_U>0</OTHER_U>
    <OTHER_M>0</OTHER_M>
    <OTHER_A>0</OTHER_A>
  </PERMISSIONS>
  <CLUSTERS>
    <ID>100</ID>
  </CLUSTERS>
  <BRIDGE><![CDATA[onebr01]]></BRIDGE>
  <BRIDGE_TYPE><![CDATA[linux]]></BRIDGE_TYPE>
  <PARENT_NETWORK_ID/>
  <VN_MAD><![CDATA[bridge]]></VN_MAD>
  <PHYDEV/>
  <VLAN_ID/>
  <OUTER_VLAN_ID/>
  <VLAN_ID_AUTOMATIC>0</VLAN_ID_AUTOMATIC>
  <OUTER_VLAN_ID_AUTOMATIC>0</OUTER_VLAN_ID_AUTOMATIC>
  <USED_LEASES>4</USED_LEASES>
  <VROUTERS/>
  <TEMPLATE>
    <BRIDGE><![CDATA[onebr01]]></BRIDGE>
    <BRIDGE_TYPE><![CDATA[linux]]></BRIDGE_TYPE>
    <DESCRIPTION><![CDATA[IPAM - onevnet02 - VLAN 2 - 10.0.0.X]]></DESCRIPTION>
    <DNS><![CDATA[192.168.0.46 192.168.0.51 192.168.0.224]]></DNS>
    <GATEWAY><![CDATA[10.0.0.1]]></GATEWAY>
    <GUEST_MTU><![CDATA[1500]]></GUEST_MTU>
    <NETWORK_ADDRESS><![CDATA[10.0.0.0]]></NETWORK_ADDRESS>
    <NETWORK_MASK><![CDATA[255.255.255.0]]></NETWORK_MASK>
    <OUTER_VLAN_ID><![CDATA[]]></OUTER_VLAN_ID>
    <PHYDEV><![CDATA[]]></PHYDEV>
    <SECURITY_GROUPS><![CDATA[0]]></SECURITY_GROUPS>
    <VLAN_ID><![CDATA[]]></VLAN_ID>
    <VN_MAD><![CDATA[bridge]]></VN_MAD>
  </TEMPLATE>
  <AR_POOL>
    <AR>
      <AR_ID><![CDATA[0]]></AR_ID>
      <DNS><![CDATA[192.168.0.46  192.168.0.51  192.168.0.224 ]]></DNS>
      <GATEWAY><![CDATA[10.0.0.1]]></GATEWAY>
      <IP><![CDATA[10.0.0.101]]></IP>
      <IPAM_ATTR><![CDATA[10.0.0.255]]></IPAM_ATTR>
      <IPAM_MAD><![CDATA[GetAutoNet]]></IPAM_MAD>
      <LOWER_LIMIT><![CDATA[10.0.0.100]]></LOWER_LIMIT>
      <MAC><![CDATA[40:32:23:04:00:01]]></MAC>
      <NETWORK_ADDRESS><![CDATA[10.0.0.0]]></NETWORK_ADDRESS>
      <NETWORK_MASK><![CDATA[255.255.255.0]]></NETWORK_MASK>
      <OTHER_IPAM_ATTR><![CDATA[mws.mds.xyz]]></OTHER_IPAM_ATTR>
      <SEARCH_DOMAIN><![CDATA[mws.mds.xyz nix.mds.xyz mds.xyz]]></SEARCH_DOMAIN>
      <SIZE><![CDATA[154]]></SIZE>
      <TYPE><![CDATA[IP4]]></TYPE>
      <UPPER_LIMIT><![CDATA[10.0.0.255]]></UPPER_LIMIT>
      <MAC_END><![CDATA[40:32:23:04:00:9a]]></MAC_END>
      <IP_END><![CDATA[10.0.0.254]]></IP_END>
      <USED_LEASES>4</USED_LEASES>
      <LEASES>
        <LEASE>
          <IP><![CDATA[10.0.0.101]]></IP>
          <MAC><![CDATA[40:32:23:04:00:01]]></MAC>
          <VM><![CDATA[45]]></VM>
        </LEASE>
        <LEASE>
          <IP><![CDATA[10.0.0.102]]></IP>
          <MAC><![CDATA[40:32:23:04:00:02]]></MAC>
          <VM><![CDATA[48]]></VM>
        </LEASE>
        <LEASE>
          <IP><![CDATA[10.0.0.103]]></IP>
          <MAC><![CDATA[40:32:23:04:00:03]]></MAC>
          <VM><![CDATA[49]]></VM>
        </LEASE>
        <LEASE>
          <IP><![CDATA[10.0.0.104]]></IP>
          <MAC><![CDATA[40:32:23:04:00:04]]></MAC>
          <VM><![CDATA[50]]></VM>
        </LEASE>
      </LEASES>
    </AR>
  </AR_POOL>
</VNET>
[oneadmin@one01 ~]$

Hello @TomK

I don’t see anything wrong there. Could you please increase the log lines and send me again the oned.log when you instantiate the template?

To increase the log lines just put (or change) the following line in your oned.conf:

LOG_CALL_FORMAT    = "Req:%i UID:%u IP:%A %m invoked %l2000"

After doing that restart OpenNebula so the change is applied.

Best,
Álex.

Hi Alejandro,

Here you go:

==> oned.log <==
Tue Jul  7 01:03:58 2020 [Z0][AuM][D]: Message received: AUTHENTICATE SUCCESS 8 -

Tue Jul  7 01:03:58 2020 [Z0][ReM][D]: Req:1856 UID:0 IP:127.0.0.1 one.template.info invoked , 3, false, false
Tue Jul  7 01:03:58 2020 [Z0][ReM][D]: Req:1856 UID:0 one.template.info result SUCCESS, "<VMTEMPLATE><ID>3</I..."
Tue Jul  7 01:03:58 2020 [Z0][ReM][D]: Req:368 UID:0 IP:127.0.0.1 one.template.instantiate invoked , 3, "GetAutoNet01.nix.mds.xyz", false, "DISK=[
  FORMAT="raw",
  SIZE="65536",
  TYPE="fs"
]
DISK=[
  IMAGE="CentOS-7-x86_64-Minimal-1908-Kickstart-Context - GV - IMG 0 - V 28",
  IMAGE_UNAME="oneadmin",
  SIZE="1277"
]

SCHED_REQUIREMENTS="ID=\"5\" | CLUSTER_ID=\"100\""
SCHED_DS_REQUIREMENTS="ID=\"129\""
NIC=[
  NETWORK_ID="26",
  SECURITY_GROUPS="0"
]

MEMORY="4096"
CPU="2"
VCPU="2"
NIC_ALIAS = []", false
Tue Jul  7 01:03:58 2020 [Z0][IPM][D]: Message received: LOG I 9 Command execution failed (exit code: 1): /var/lib/one/remotes/ipam/GetAutoNet/get_address 9

Tue Jul  7 01:03:58 2020 [Z0][IPM][I]: Command execution failed (exit code: 1): /var/lib/one/remotes/ipam/GetAutoNet/get_address 9
Tue Jul  7 01:03:58 2020 [Z0][IPM][D]: Message received: GET_ADDRESS FAILURE 9 LQ==

Tue Jul  7 01:03:58 2020 [Z0][IPM][E]: LQ==
Tue Jul  7 01:03:58 2020 [Z0][ONE][E]: Cannot get IP/MAC lease from virtual network 26.
Tue Jul  7 01:03:58 2020 [Z0][ReM][E]: Req:368 UID:0 one.template.instantiate result FAILURE [one.template.instantiate] Error allocating a new virtual machine template. Cannot get IP/MAC lease from virtual network 26.

==> sunstone.log <==
Tue Jul 07 01:03:58 2020 [I]: 192.168.0.81 - - [07/Jul/2020:01:03:58 -0400] "POST /vmtemplate/3/action HTTP/1.1" 500 - 0.8514

==> oned.log <==
Tue Jul  7 01:04:11 2020 [Z0][ReM][D]: Req:5216 UID:0 IP:127.0.0.1 one.zone.raftstatus invoked
Tue Jul  7 01:04:11 2020 [Z0][ReM][D]: Req:5216 UID:0 one.zone.raftstatus result SUCCESS, "<RAFT><SERVER_ID>-1<..."
Tue Jul  7 01:04:11 2020 [Z0][ReM][D]: Req:7136 UID:0 IP:127.0.0.1 one.vmpool.infoextended invoked , -2, -1, -1, -1
Tue Jul  7 01:04:11 2020 [Z0][ReM][D]: Req:7136 UID:0 one.vmpool.infoextended result SUCCESS, "<VM_POOL><VM><ID>50<..."
Tue Jul  7 01:04:11 2020 [Z0][ReM][D]: Req:7120 UID:0 IP:127.0.0.1 one.vmpool.infoextended invoked , -2, -1, -1, -1
Tue Jul  7 01:04:11 2020 [Z0][ReM][D]: Req:7120 UID:0 one.vmpool.infoextended result SUCCESS, "<VM_POOL><VM><ID>50<..."
Tue Jul  7 01:04:20 2020 [Z0][ReM][D]: Req:3728 UID:1 IP:127.0.0.1 one.documentpool.info invoked , -2, -1, -1, 100
Tue Jul  7 01:04:20 2020 [Z0][ReM][D]: Req:3728 UID:1 one.documentpool.info result SUCCESS, "<DOCUMENT_POOL></DOC..."
Tue Jul  7 01:04:26 2020 [Z0][InM][D]: Host mdskvm-p06.nix.mds.xyz (5) successfully monitored.
Tue Jul  7 01:04:26 2020 [Z0][VMM][D]: VM 48 successfully monitored: STATE=a CPU=0.0 MEMORY=652564 NETRX=343177863 NETTX=1642021 DISKRDBYTES=219267660 DISKWRBYTES=330772992 DISKRDIOPS=64125 DISKWRIOPS=42509
Tue Jul  7 01:04:26 2020 [Z0][VMM][D]: VM 49 successfully monitored: STATE=a CPU=0.0 MEMORY=656584 NETRX=343206888 NETTX=1665850 DISKRDBYTES=220246092 DISKWRBYTES=334005248 DISKRDIOPS=65802 DISKWRIOPS=42961
^C
[root@one01 one]#

I’ve set the LOG_CALL_FORMAT before instantiating, and restarted opennebula services (systemctl restart opennebula opennebula-sunstone):

[root@one01 one]# grep LOG_CALL_FORMAT /etc/one/oned.conf
#  LOG_CALL_FORMAT: Format string to log XML-RPC calls. Interpreted strings:
#LOG_CALL_FORMAT    = "Req:%i UID:%u IP:%A %m invoked %l20"
LOG_CALL_FORMAT    = "Req:%i UID:%u IP:%A %m invoked %l2000"
[root@one01 one]#

GetAutoNet.log.tar.gz (6.9 KB)
one01-logs.tar.gz (32.8 KB)

Attached /var/log/one/*.log files from one01.nix.mds.xyz ( OpenNebula Server ). The above inline snippet is from a tail -f of the log files while an instance was being instantiated from the UI. Hopefully this will give more context.

Included attached GetAutoNet logs though those are likely not as relevant given that only a number is passed as a parameter.

Thx,
TK

Hello @TomK

I finally get what’s going on, the information that the driver needs is passed by STDIN, that’s why you are not seeing anything in the arguments. So in your script you should read from stdin using STDIN.read function.

Best,
Álex.

Thanks very much Alejandro!

I’ll try this in the next few days and report back.