Problems starting VMs after upgrading pool master from XenServer 6.5 to XCP-ng

[vegarnilsen]

We have a XenServer 6.5 pool with 7 hosts that I want to upgrade to XCP-ng. All VMs are on shared storage (NFS).

I've migrated VMs away from two of the hosts so that I have two hosts to play with for the upgrade, and attempted both an upgrade from XS6.5 to XCP-ng 7.5 and to XCP-ng 7.6, with both of those two hosts as the current pool master. After I've upgraded the pool master and it's finished booted up, I've ran xe-toolstack-restart on the remaining pool members and waited until XCP-ng Center says all is good with the pool.

I have a couple of non-essential VMs in the pool that were shut down during the upgrade, after upgrading the pool master I've tried starting one of them on the upgraded host, leading to this error message (after about 10 minutes or so of waiting):

"Failed","Starting VM 'dhcp01.' on 'oslo5pool1h05'
Internal error: xenopsd internal error: Storage_interface.Internal_error("Unix.Unix_error(Unix.EMFILE, \"open\", \"/dev/urandom\")")
Time: 00:01:07","oslo5pool1h05","Dec 27, 2018 10:24 AM"

I'm also seeing error messages like this in /var/log/xensource.log on the upgraded pool master (this example from attempting an upgrade of the other host as shown by the hostname):

Dec 27 15:15:48 oslo5pool1h06 xapi: [debug|oslo5pool1h06|915 db_gc||db_gc] Exception in DB GC thread: INTERNAL_ERROR: [ (Sys_error "/var/lib/xcp/blobs/messages: Too many open files") ]
Dec 27 15:15:50 oslo5pool1h06 xapi: [debug|oslo5pool1h06|33 dbflush [/var/lib/xcp/state.db]||sql] Exception in DB flushing thread: Unix.Unix_error(Unix.EMFILE, "open", "/var/lib/xcp/93b2f2a1-ad4d-427b-a68f-e0838807c4eb")
Dec 27 15:15:52 oslo5pool1h06 xapi: [debug|oslo5pool1h06|33 dbflush [/var/lib/xcp/state.db]||sql] Exception in DB flushing thread: Unix.Unix_error(Unix.EMFILE, "open", "/var/lib/xcp/3485d05e-04a0-4991-ad46-82c96ce6c12f")
Dec 27 15:15:52 oslo5pool1h06 xapi: [debug|oslo5pool1h06|946 |monitor_dbcalls D:1b323c047d4f|monitor_dbcalls] monitor_dbcall_thread would have died from: INTERNAL_ERROR: [ Network_stats.Read_error ]; restarting in 30s.
Dec 27 15:15:53 oslo5pool1h06 xcp-networkd: [ info|oslo5pool1h06|1 |monitor_thread|network_utils] /usr/bin/ovs-appctl bond/show bond0
Dec 27 15:15:53 oslo5pool1h06 xcp-networkd: [ info|oslo5pool1h06|1 |monitor_thread|network_utils] /usr/bin/ovs-vsctl --timeout=20 get port bond0 bond_mode
Dec 27 15:15:54 oslo5pool1h06 xapi: [debug|oslo5pool1h06|33 dbflush [/var/lib/xcp/state.db]||sql] Exception in DB flushing thread: Unix.Unix_error(Unix.EMFILE, "open", "/var/lib/xcp/5fa83dcc-6cb1-4861-93e2-9df13cffa639")
Dec 27 15:15:56 oslo5pool1h06 xapi: [debug|oslo5pool1h06|916 INET :::80||server_io] Caught Unix exception in accept: Too many open files in accept
Dec 27 15:15:56 oslo5pool1h06 xapi: [debug|oslo5pool1h06|17 UNIX /var/lib/xcp/xapi||server_io] Caught Unix exception in accept: Too many open files in accept
Dec 27 15:15:56 oslo5pool1h06 xapi: [debug|oslo5pool1h06|33 dbflush [/var/lib/xcp/state.db]||sql] Exception in DB flushing thread: Unix.Unix_error(Unix.EMFILE, "open", "/var/lib/xcp/2308f24b-013a-45c9-bddb-d8c7fdd34004")

[root@oslo5pool1h06 ~]# cat /proc/sys/fs/file-nr
10944	0	399875

I've reverted the pool back to XS6.5 (the backup and restore is thankfully working like a charm, kudos on that), but if there's anything I can do to debug this let me know.

[olivierlambert]

Can you check if your current time is correct and/or if you have a ntp sync working? (ntpq -p)

[vegarnilsen]

All of the hosts are running NTP (in XenServer 6.5):

➜  xcp-ng git:(master) ansible oslo5pool1 -m raw -u root -a "/usr/sbin/ntpq -p; date"
oslo5pool1h01 | CHANGED | rc=0 >>
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 LOCAL(0)        .LOCL.          10 l  52d   64    0    0.000    0.000   0.000
+time01.ops.opss 162.23.41.55     2 u  491 1024  377   50.922    5.339   0.801
+c4.cap.fidesz.h 195.111.92.55    3 u  303 1024  377   46.668   -0.190   0.575
*dns02.wsrs.net  193.79.237.14    2 u  196 1024  377   25.374   -2.696   5.402
Fri Dec 28 13:51:45 CET 2018

oslo5pool1h02 | CHANGED | rc=0 >>
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 LOCAL(0)        .LOCL.          10 l  52d   64    0    0.000    0.000   0.000
+ntp.suas.cz     147.231.2.6      2 u  365 1024  377   51.438    1.151   0.241
*server1.webster 193.190.230.65   2 u  555 1024  377   30.331   -2.483   0.266
 62.4.3.34       37.187.5.167     3 u  41d 1024    0   35.571  -625190   0.000
Fri Dec 28 13:51:45 CET 2018

oslo5pool1h05 | CHANGED | rc=0 >>
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 LOCAL(0)        .LOCL.          10 l  860   64    0    0.000    0.000   0.000
xtime0.campinggl 192.53.103.108   2 u   70  128  377    1.169   16.985   3.749
*time1.campinggl .PPS.            1 u  113  128  377    2.201    2.754   0.445
Fri Dec 28 13:51:45 CET 2018

oslo5pool1h03 | CHANGED | rc=0 >>
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 LOCAL(0)        .LOCL.          10 l 204d   64    0    0.000    0.000   0.000
*ip139.ip-5-196- 145.238.203.14   2 u 1047 1024  377   29.410    0.680   0.392
+46.28.110.244   89.221.210.188   3 u   71 1024  377   50.128   -3.707   0.787
+dedi-fr-481781. 130.149.17.8     2 u 1004 1024  377   30.524    0.173   0.239
Fri Dec 28 13:51:45 CET 2018

oslo5pool1h04 | CHANGED | rc=0 >>
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 LOCAL(0)        .LOCL.          10 l  10h   64    0    0.000    0.000   0.000
*menkisyscloudsr .BCS.            1 u  718 1024  377   30.959    1.581   9.767
+5.20.0.41       132.246.11.231   2 u  671 1024  377   53.278   19.241   1.008
 static.53.56.9. 130.88.212.143   3 u   9d 1024    0   34.363   -8.330   0.000
Fri Dec 28 13:51:45 CET 2018

oslo5pool1h06 | CHANGED | rc=0 >>
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 LOCAL(0)        .LOCL.          10 l 1018   64    0    0.000    0.000   0.000
xtime0.campinggl 192.53.103.108   2 u   88  128  377    1.116   25.843   5.247
*time1.campinggl .PPS.            1 u  102  128  377    1.826   10.377   0.447
Fri Dec 28 13:51:45 CET 2018

oslo5pool1h07 | CHANGED | rc=0 >>
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
*LOCAL(0)        .LOCL.          10 l   26   64  377    0.000    0.000   0.001
xtime0.campinggl 192.53.103.108   2 u   57   64  377    1.274   11.614  15.196
+time1.campinggl .PPS.            1 u   19   64  377    1.918   -0.028   0.191
Fri Dec 28 13:51:45 CET 2018

[olivierlambert]

Did you change the partition layout? If not, that's likely the cause of the issue (not enough space on root partition after the upgrade).

[vegarnilsen]

Did you change the partition layout? If not, that's likely the cause of the issue (not enough space on root partition after the upgrade).

Yes, this is with the new layout. I'm doing a new upgrade now to verify that it keeps the NTP settings sane.

[olivierlambert]

Okay so when the upgrade is done, double check:

• your partitions layout
• if there is any full partition
• NTP settings

You can also kill XAPI, change the max open files number with ulimit and check the result.

[vegarnilsen]

After upgrade (before it's started mounting NFS shares):

[root@oslo5pool1h05 ~]# df -h
Filesystem      Size  Used Avail Use% Mounted on
devtmpfs        2.0G     0  2.0G   0% /dev
tmpfs           2.0G   44K  2.0G   1% /dev/shm
tmpfs           2.0G 1008K  2.0G   1% /run
tmpfs           2.0G     0  2.0G   0% /sys/fs/cgroup
/dev/sda1        18G  1.9G   15G  11% /
xenstore        2.0G     0  2.0G   0% /var/lib/xenstored
/dev/loop0      8.0M  8.0M     0 100% /var/xen/xc-install
/dev/sda5       3.9G  9.6M  3.7G   1% /var/log
tmpfs           393M     0  393M   0% /run/user/0
[root@oslo5pool1h05 ~]# df -hi
Filesystem      Inodes IUsed IFree IUse% Mounted on
devtmpfs        489K   543  488K    1% /dev
tmpfs           491K     8  491K    1% /dev/shm
tmpfs           491K   986  490K    1% /run
tmpfs           491K    11  491K    1% /sys/fs/cgroup
/dev/sda1       1.2M   50K  1.1M    5% /
xenstore        491K     1  491K    1% /var/lib/xenstored
/dev/loop0         0     0     0     - /var/xen/xc-install
/dev/sda5       256K    65  256K    1% /var/log
tmpfs           491K     1  491K    1% /run/user/0
[root@oslo5pool1h05 ~]# date
Fri Dec 28 14:48:17 CET 2018
[root@oslo5pool1h05 ~]# ntpq -p
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
xtime0.campinggl 192.53.103.108   2 u   22   64    1    2.260    4.976   0.000
*time1.campinggl .PPS.            1 u   21   64    1    2.435    0.300   0.000

Changed file number limit:

[root@oslo5pool1h05 ~]# vi /etc/systemd/system/xapi.service.d/local.conf 
[root@oslo5pool1h05 ~]# systemctl daemon-reload 
[root@oslo5pool1h05 ~]# systemctl cat xapi | grep Limit
LimitNOFILE=65536
[root@oslo5pool1h05 ~]# systemctl restart xapi
[root@oslo5pool1h05 ~]# systemctl status xapi
● xapi.service - XenAPI server (XAPI)
   Loaded: loaded (/usr/lib/systemd/system/xapi.service; enabled; vendor preset: enabled)
  Drop-In: /etc/systemd/system/xapi.service.d
           └─local.conf, slice.conf
   Active: active (running) since Fri 2018-12-28 15:04:01 CET; 3s ago
  Process: 5402 ExecStopPost=/usr/bin/rm -f /var/lock/subsys/xapi /var/run/xapi.pid /var/run/xapi_startup.cookie /var/run/xapi_init_complete.cookie (code=exited, status=0/SUCCESS)
  Process: 4732 ExecStop=/opt/xensource/libexec/xapi-init stop (code=killed, signal=TERM)
  Process: 5413 ExecStartPost=/usr/bin/touch /var/lock/subsys/xapi (code=exited, status=0/SUCCESS)
 Main PID: 5411 (xapi)
   CGroup: /control.slice/xapi.service
           └─5411 /opt/xensource/bin/xapi -nowatchdog -writereadyfile /var/run/xapi_startup.cooki...

Then I attempted to start a stopped VM on the upgraded pool master. Didn't work, but with a different error message than before:

"Failed","Starting VM 'd3stage02' on 'oslo5pool1h05'
Internal error: xenopsd internal error: Storage_interface.Internal_error("Unix.Unix_error(Unix.EINVAL, \"select\", \"\")")
Time: 00:00:40","oslo5pool1h05","Dec 28, 2018 3:06 PM"```

(The NFS share for this VM is mounted on all hosts in the pool.)

[olivierlambert]

There is something weird, but it's hard to pinpoint it from here :/

Pinging @rushikeshjadhav if he can spot something, otherwise it would require to take support to dig more on this with a remote SSH thing and doing a proper investigation.

[vegarnilsen]

There is something weird, but it's hard to pinpoint it from here :/

Yup, completely understood. Thanks so far.

[rushikeshjadhav]

@vegarnilsen since your VMs are on NFS, before starting them, do you see your SR mounted correctly (ls, touch) ? What does /var/log/SMlog says while you try to start VMs?

[vegarnilsen]

@vegarnilsen since your VMs are on NFS, before starting them, do you see your SR mounted correctly (ls, touch) ?

It looked ok, but I didn't check that they were writeable.

What does /var/log/SMlog says while you try to start VMs?

I won't have time to check this week, but I'll try another upgrade next week and check then. (I have to revert the pool back to XS 6.5 since it is in production and I can't leave it in a semi-upgraded state for too long since that blocks a number of VM operations.)

[vegarnilsen]

I tested another upgrade yesterday, and this time I was actually able to start up one of my test VMs on the upgraded host. However, XAPI was very unstable on that host, XCP-ng Center lost connection every couple of minutes, and after about 20-25 minutes I lost connection to the host entirely. Thus I reverted it back to 6.5 again.

While I was starting the VM I got a ton of messages like this in /var/log/SMlog:

Jan  8 20:26:10 oslo5pool1h05 SM: [23615] lock: opening lock file /var/lock/sm/57fbfa0c-a440-b4aa-7c0d-a657be77272b/sr
Jan  8 20:26:10 oslo5pool1h05 SM: [23615] ***** NFS VHD: EXCEPTION <class 'xmlrpclib.Fault'>, <Fault 401: 'You must log in'>
Jan  8 20:26:10 oslo5pool1h05 SM: [23615]   File "/opt/xensource/sm/SRCommand.py", line 370, in run
Jan  8 20:26:10 oslo5pool1h05 SM: [23615]     sr = driver(cmd, cmd.sr_uuid)
Jan  8 20:26:10 oslo5pool1h05 SM: [23615]   File "/opt/xensource/sm/FileSR.py", line 83, in __init__
Jan  8 20:26:10 oslo5pool1h05 SM: [23615]     SR.SR.__init__(self, srcmd, sr_uuid)
Jan  8 20:26:10 oslo5pool1h05 SM: [23615]   File "/opt/xensource/sm/SR.py", line 147, in __init__
Jan  8 20:26:10 oslo5pool1h05 SM: [23615]     self.load(sr_uuid)
Jan  8 20:26:10 oslo5pool1h05 SM: [23615]   File "/opt/xensource/sm/NFSSR", line 80, in load
Jan  8 20:26:10 oslo5pool1h05 SM: [23615]     self.sm_config = self.session.xenapi.SR.get_sm_config(self.sr_ref)
Jan  8 20:26:10 oslo5pool1h05 SM: [23615]   File "/usr/lib/python2.7/site-packages/XenAPI.py", line 264, in __call__
Jan  8 20:26:10 oslo5pool1h05 SM: [23615]     return self.__send(self.__name, args)
Jan  8 20:26:10 oslo5pool1h05 SM: [23615]   File "/usr/lib/python2.7/site-packages/XenAPI.py", line 167, in xenapi_request
Jan  8 20:26:10 oslo5pool1h05 SM: [23615]     raise xmlrpclib.Fault(401, 'You must log in')
Jan  8 20:26:10 oslo5pool1h05 SM: [23615]
Jan  8 20:26:10 oslo5pool1h05 SM: [23615] lock: closed /var/lock/sm/57fbfa0c-a440-b4aa-7c0d-a657be77272b/sr
[…]
Jan  8 20:26:30 oslo5pool1h05 SM: [27289] lock: opening lock file /var/lock/sm/57fbfa0c-a440-b4aa-7c0d-a657be77272b/sr
Jan  8 20:26:31 oslo5pool1h05 SM: [27289] lock: acquired /var/lock/sm/57fbfa0c-a440-b4aa-7c0d-a657be77272b/sr
Jan  8 20:26:31 oslo5pool1h05 SM: [27289] ['/usr/sbin/td-util', 'query', 'vhd', '-vpfb', '/var/run/sr-mount/57fbfa0c-a440-b4aa-7c0d-a657be77272b/a4a2da06-b2d7-4f1c-9c8c-eec071b5ab72.vhd']
Jan  8 20:26:31 oslo5pool1h05 SM: [27289]   pread SUCCESS
Jan  8 20:26:31 oslo5pool1h05 SM: [27289] lock: released /var/lock/sm/57fbfa0c-a440-b4aa-7c0d-a657be77272b/sr
Jan  8 20:26:31 oslo5pool1h05 SM: [27289] vdi_epoch_begin {'sr_uuid': '57fbfa0c-a440-b4aa-7c0d-a657be77272b', 'subtask_of': 'DummyRef:|c4f98d35-e410-407d-bbc7-15b17948e1b5|VDI.epoch_begin', 'vdi_ref': 'OpaqueRef:ca426df4-3386-6163-9687-4a804f00f3b8', 'vdi_on_boot': 'persist', 'args': [], 'o_direct': False, 'vdi_location': 'a4a2da06-b2d7-4f1c-9c8c-eec071b5ab72', 'host_ref': 'OpaqueRef:c0014693-02ad-56d3-c08b-d4969be67729', 'session_ref': 'OpaqueRef:4d031ea2-904d-43d7-a0e4-330d48db0b1d', 'device_config': {'SRmaster': 'true', 'serverpath': '/nfs5024/vms/test02vn', 'server': 'nfs5024'}, 'command': 'vdi_epoch_begin', 'vdi_allow_caching': 'false', 'sr_ref': 'OpaqueRef:a10462e0-3055-157a-6a30-2eeed8ccde79', 'vdi_uuid': 'a4a2da06-b2d7-4f1c-9c8c-eec071b5ab72'}
Jan  8 20:26:31 oslo5pool1h05 SM: [27289] lock: closed /var/lock/sm/57fbfa0c-a440-b4aa-7c0d-a657be77272b/sr

(Basically one such pair of failure and success for each of our approx. 370 NFS SRs.)
This was the only log entry directly related to starting the VM that I could find:

Jan  8 20:26:30 oslo5pool1h05 snapwatchd: [2177] XS-PATH -> /vss/6714648c-cf08-8b69-bfae-01d0a6a5ed1b
Jan  8 20:26:30 oslo5pool1h05 snapwatchd: [2177] XS-PATH -> /vss/6714648c-cf08-8b69-bfae-01d0a6a5ed1b

The SR was mounted properly and was writeable after the upgrade.

[root@oslo5pool1h05 ~]# xe sr-list uuid=57fbfa0c-a440-b4aa-7c0d-a657be77272b
uuid ( RO)                : 57fbfa0c-a440-b4aa-7c0d-a657be77272b
          name-label ( RW): test02vn nfs5024
    name-description ( RW): test02vn nfs5024
                host ( RO): <shared>
                type ( RO): nfs
        content-type ( RO): user
[root@oslo5pool1h05 ~]# ls -lh /var/run/sr-mount/57fbfa0c-a440-b4aa-7c0d-a657be77272b
total 1.9G
-rw-r--r-- 1 root root 1.9G Nov 26 12:04 1a7b5446-0476-4f1b-9ce5-19cee6c1646a.vhd
-rw-r--r-- 1 root root 2.0G Jan  8 20:37 a4a2da06-b2d7-4f1c-9c8c-eec071b5ab72.vhd
-rw-r--r-- 1 root root  29K Nov 26 16:16 d6b211df-b029-4c36-aa89-60d67dd280be.vhd
-rw-r--r-- 1 root root 7.3K Nov 26 16:16 filelog.txt
[root@oslo5pool1h05 ~]# df -h /var/run/sr-mount/57fbfa0c-a440-b4aa-7c0d-a657be77272b
Filesystem            Size  Used Avail Use% Mounted on
nfs5024:/nfs5024/vms/test02vn/57fbfa0c-a440-b4aa-7c0d-a657be77272b
                      1.1T  1.9G  1.1T   1% /var/run/sr-mount/57fbfa0c-a440-b4aa-7c0d-a657be77272b

[stormi]

Hi. Do you still have those upgrade issues?

[vegarnilsen]

Hi. Do you still have those upgrade issues?

@stormi I haven't tested again after the last comment. For now I'm waiting for the next version of XCP-ng until I spend more time on this.

[borzel]

How did you test this? You mentioned two pool masters?

I assume you

• removed the two testhosts from your productive pool
• created a new XS6.5 pool
• upgraded this testpool (using another NFS share, not the productive one)