celery: UnicodeEncodeError: 'ascii' codec can't encode character u'\u9a6c' in position 0: ordinal not in range(128)

[yongshengma]

Hello,

I converted a qcow2 image to a raw image into/under vpool mount point, but the device name contains a few Chinese characters. Then vdisks list page became empty and its api returns 500 error.

May 23 15:30:00 Node-43 celery: 2019-05-23 15:30:00 16300 +0800 - Node-43 - 17135/140243007780672 - celery/log.py - log - 20 - ERROR - Task ovs.vdisk.sync_with_reality[535558d9-b4ad-41b5-b6ef-4ef916a75c84] raised unexpected: UnicodeEncodeError('ascii', u'\u9a6c', 0, 1, 'ordinal not in range(128)')
May 23 15:30:00 Node-43 celery: UnicodeEncodeError: 'ascii' codec can't encode character u'\u9a6c' in position 0: ordinal not in range(128)

I guess the Chinese chars could be the cause to this issue, so I removed that raw file such as rm /mnt/vpool/xxx.raw . However, the log above still coming out when vdisks list page is accessed. Of coz the page is still empty.

Is that device name saved somewhere?
Best regards
Yongsheng

[JeffreyDevloo]

Hi Yongshengma

Converting the image made the volumedriver trigger the create event on which the Framework responds. The Framework enforces ascii encoding when saving objects to the OVSDB Arakoon (through the ujson serialization)
Since it can't encode the name (that is what I'm hoping given the error, no real other context), I suspect it isn't yet stored inside the OVSDB.

The following suggestion will not work if the Framework already stored the key inside Arakoon as decoding it would be impossible with the current implementation. If this is the case, reply back to this ticket and I'll see how I can assist you further.

from ovs.dal.lists.vdisklist import VDiskList
from ovs.dal.lists.vpoollist import VPoolList
devicename = "<INSERT NAME HERE>"
vpool_name = "<INSERT VPOOL NAME HERE>"
vpool = VPoolList.get_vpool_by_name(vpool_name)
vdisk = VDiskList.get_by_devicename_and_vpool(devicename, vpool)
if not vdisk:
    # Try an alternative route
    for vd in VDiskList.get_vdisks():
        # Edit: devicename iso device_name
        if devicename in vd.devicename:
            print 'Found it!'
            vdisk = vd
            break
if not vdisk:
    print 'Found nothing'
else:
    # VDisk is now usable. The framework managed to store it internally
    print vdisk.guid

If the snippet above raises any exception regarding decoding, we will have to resolve it differently.
If no vdisk is found but len(VDiskList.get_vdisks()) works as excepted, the issue lies in syncing up with the volumedriver which would mean renaming/removing the volume there.

Side note:
The error message you provide is not from the vdisk list. It's coming from the Framework trying to sync up the volumes of the volumedriver into its own database. This error will have occurred when processing the volumedriver event.

For future exceptions: it's better to log the stacktrace as seen in the ovs-workers logs as it would provide more context.

Best regards

[yongshengma]

Hi @JeffreyDevloo

I replicated this issue in a test env, so look at these lines please:

In [1]: from ovs.dal.lists.vdisklist import VDiskList

In [2]: from ovs.dal.lists.vpoollist import VPoolList

In [3]: devicename = "马.raw"

In [4]: vpool_name = "pool-3"

In [5]: vpool = VPoolList.get_vpool_by_name(vpool_name)

In [6]: vdisk = VDiskList.get_by_devicename_and_vpool(devicename, vpool)
/opt/UniStor/ovs/dal/datalist.py:298: UnicodeWarning: Unicode equal comparison failed to convert both arguments to Unicode - interpreting them as being unequal
  return value == item[2], instance

In [7]: print vdisk
None

In [8]: if not vdisk:
   ...:         # Try an alternative route
   ...:         for vd in VDiskList.get_vdisks():
   ...:                 if devicename in vdisk.device_name:
   ...:                         print 'Found it!'
   ...:                         vdisk = vd
   ...:                         break
   ...:         
---------------------------------------------------------------------------
AttributeError                            Traceback (most recent call last)
<ipython-input-8-2c521981e957> in <module>()
      2         # Try an alternative route
      3         for vd in VDiskList.get_vdisks():
----> 4                 if devicename in vdisk.device_name:
      5                         print 'Found it!'
      6                         vdisk = vd

AttributeError: 'NoneType' object has no attribute 'device_name'

In [9]: 

In [9]: len(VDiskList.get_vdisks())
Out[9]: 9

The returned number of len(VDiskList.get_vdisks()) is one more than ls /mnt/vpool/.

Happenly a task snapshot_all_vdisks info in which there are 7 vdisks and 1 vtemplate:

May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 71200 +0800 - Node-41 - 21741/140566430168896 - lib/generic.py - snapshot_all_vdisks - 24 - INFO - [SSA] Snapshot has been taken for 7 vDisks, 1 failed.

May that failed one be the removed one with special chars?

More context:

May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 31700 +0800 - Node-41 - 21671/140566430168896 - celery/strategy.py - task_message_handler - 286 - INFO - Received task: ovs.generic.snapshot_all_vdisks[ca7ff8c2-7cca-4dc4-bc6c-ea3a68660ff4]
May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 32200 +0800 - Node-41 - 21741/140566430168896 - lib/decorators.py - log_message - 14 - INFO - Ensure single DEFAULT mode - ID 1558670399_yEpzAWNQhv - Setting key ovs_ensure_single_ovs.generic.snapshot_all_vdisks
May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 32500 +0800 - Node-41 - 21741/140566430168896 - lib/generic.py - snapshot_all_vdisks - 15 - INFO - [SSA] started
May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 35300 +0800 - Node-41 - 21741/140566430168896 - lib/vdisk.py - create_snapshots - 16 - INFO - Create inconsistent snapshot for vDisk junk-5
May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 38900 +0800 - Node-41 - 21741/140566430168896 - lib/vdisk.py - create_snapshots - 17 - INFO - Create inconsistent snapshot for vDisk junk-1
May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 42200 +0800 - Node-41 - 21741/140566430168896 - lib/vdisk.py - create_snapshots - 18 - INFO - Create inconsistent snapshot for vDisk disk-10
May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 47300 +0800 - Node-41 - 21741/140566430168896 - lib/vdisk.py - create_snapshots - 19 - INFO - Create inconsistent snapshot for vDisk junk-3
May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 50200 +0800 - Node-41 - 21741/140566430168896 - lib/generic.py - snapshot_all_vdisks - 20 - ERROR - Error taking snapshot for vDisk b530ab26-e128-42e6-bf25-c0461b668faa
May 24 11:59:59 Node-41 celery[21671]: Traceback (most recent call last):
May 24 11:59:59 Node-41 celery[21671]: File "/opt/OpenvStorage/ovs/lib/generic.py", line 80, in snapshot_all_vdisks
May 24 11:59:59 Node-41 celery[21671]: metadata=metadata)
May 24 11:59:59 Node-41 celery[21671]: File "/usr/lib/python2.7/site-packages/celery/local.py", line 188, in __call__
May 24 11:59:59 Node-41 celery[21671]: return self._get_current_object()(*a, **kw)
May 24 11:59:59 Node-41 celery[21671]: File "/usr/lib/python2.7/site-packages/celery/app/trace.py", line 439, in __protected_call__
May 24 11:59:59 Node-41 celery[21671]: return orig(self, *args, **kwargs)
May 24 11:59:59 Node-41 celery[21671]: File "/usr/lib/python2.7/site-packages/celery/app/task.py", line 420, in __call__
May 24 11:59:59 Node-41 celery[21671]: return self.run(*args, **kwargs)
May 24 11:59:59 Node-41 celery[21671]: File "/opt/OpenvStorage/ovs/lib/vdisk.py", line 502, in create_snapshot
May 24 11:59:59 Node-41 celery[21671]: raise RuntimeError(vdisk_result[1])
May 24 11:59:59 Node-41 celery[21671]: RuntimeError: Throw location unknown (consider using BOOST_THROW_EXCEPTION)
May 24 11:59:59 Node-41 celery[21671]: Dynamic exception type: volumedriverfs::ObjectNotRegisteredException
May 24 11:59:59 Node-41 celery[21671]: std::exception::what: std::exception
May 24 11:59:59 Node-41 celery[21671]: [volumedriverfs::tag_volume_id*] = bc23f688-b583-40cd-be4f-312647c3a211
May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 62400 +0800 - Node-41 - 21741/140566430168896 - lib/vdisk.py - create_snapshots - 21 - INFO - Create inconsistent snapshot for vDisk junk-7
May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 65100 +0800 - Node-41 - 21741/140566430168896 - lib/vdisk.py - create_snapshots - 22 - INFO - Create inconsistent snapshot for vDisk disk-22
May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 69500 +0800 - Node-41 - 21741/140566430168896 - lib/vdisk.py - create_snapshots - 23 - INFO - Create inconsistent snapshot for vDisk junk-2
May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 71200 +0800 - Node-41 - 21741/140566430168896 - lib/generic.py - snapshot_all_vdisks - 24 - INFO - [SSA] Snapshot has been taken for 7 vDisks, 1 failed.
May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 71200 +0800 - Node-41 - 21741/140566430168896 - lib/decorators.py - log_message - 25 - INFO - Ensure single DEFAULT mode - ID 1558670399_yEpzAWNQhv - Task ovs.generic.snapshot_all_vdisks finished successfully
May 24 11:59:59 Node-41 celery[21671]: 2019-05-24 11:59:59 71300 +0800 - Node-41 - 21741/140566430168896 - lib/decorators.py - log_message - 26 - INFO - Ensure single DEFAULT mode - ID 1558670399_yEpzAWNQhv - Deleting key ovs_ensure_single_ovs.generic.snapshot_all_vdisks

[yongshengma]

I;m afraid you made a typo mistake on device_name, so I did a little differently:

In [12]: for vd in VDiskList.get_vdisks():
   ....:         print vd.devicename
   ....:     
/vdisk-temp.raw
/junk-5.raw
/junk-1.raw
/disk-10.raw
/junk-3.raw
/马.raw
/junk-7.raw
/disk-22.raw
/junk-2.raw

In [13]: 

You can see that heterogeneous vdisk name shows up in the list, but it has actually been removed by me.

Continue

In [13]: if not vdisk:
   ....:         # Try an alternative route
   ....:         for vd in VDiskList.get_vdisks():
   ....:                 if devicename in vdisk.devicename:
   ....:                         print 'Found it!'
   ....:                         vdisk = vd
   ....:                         break
   ....:         
---------------------------------------------------------------------------
AttributeError                            Traceback (most recent call last)
<ipython-input-13-88bcc8483f6b> in <module>()
      2         # Try an alternative route
      3         for vd in VDiskList.get_vdisks():
----> 4                 if devicename in vdisk.devicename:
      5                         print 'Found it!'
      6                         vdisk = vd

AttributeError: 'NoneType' object has no attribute 'devicename'

[yongshengma]

In [5]: for vd in VDiskList.get_vdisks():
   ...:         print vd.guid, vd.devicename
   ...:     
1e809b46-69bf-48ff-8280-e05e73692df1 /vdisk-temp.raw
560ef179-2a56-4a4d-ac2b-0b5fb52d7a16 /junk-5.raw
7d22df05-a317-4d67-93d5-d2118524b515 /junk-1.raw
87f43cd6-286f-47d9-a000-4f8a5afcb001 /disk-10.raw
a7bd1a3e-cf6e-4639-8806-7e31fed63974 /junk-3.raw
b530ab26-e128-42e6-bf25-c0461b668faa /马.raw
ba4f6b3c-8230-4e02-aabb-af9baa91b067 /junk-7.raw
c9d82503-6d4f-4c3b-8c0d-e87e2b958a07 /disk-22.raw
cfdf5a45-bb08-448c-98c4-f68bb58937b4 /junk-2.raw

In [6]: 

In [6]: from ovs.lib.vdisk import VDiskController

In [7]: vdisk_guid = 'b530ab26-e128-42e6-bf25-c0461b668faa'

In [8]: VDiskController.delete(vdisk_guid)
2019-05-24 15:12:12 56700 +0800 - Node-42 - 5091/140202688362304 - hybrids/storagerouter.py - _features - 0 - ERROR - Could not load feature information
Traceback (most recent call last):
  File "/opt/OpenvStorage/ovs/dal/hybrids/storagerouter.py", line 162, in _features
    client = SSHClient(self, username='root')
  File "/opt/OpenvStorage/ovs/extensions/generic/sshclient.py", line 52, in __init__
    storagerouter = StorageRouter(endpoint.guid)
  File "/opt/OpenvStorage/ovs/dal/dataobject.py", line 238, in __init__
    self.__class__.__name__, self._guid
ObjectNotFoundException: StorageRouter with guid 'a8c998b5-efc0-40e5-b835-d5ea77c5deea' could not be found
---------------------------------------------------------------------------
TypeError                                 Traceback (most recent call last)
<ipython-input-8-4a8f279942cb> in <module>()
----> 1 VDiskController.delete(vdisk_guid)

/usr/lib/python2.7/site-packages/celery/local.pyc in __call__(self, *a, **kw)
    186 
    187     def __call__(self, *a, **kw):
--> 188         return self._get_current_object()(*a, **kw)
    189 
    190     def __len__(self):

/usr/lib/python2.7/site-packages/celery/app/task.pyc in __call__(self, *args, **kwargs)
    418             if self.__self__ is not None:
    419                 return self.run(self.__self__, *args, **kwargs)
--> 420             return self.run(*args, **kwargs)
    421         finally:
    422             self.pop_request()

/opt/OpenvStorage/ovs/lib/vdisk.pyc in delete(vdisk_guid)
    199         vdisk.invalidate_dynamics('storagerouter_guid')
    200         storagerouter = StorageRouter(vdisk.storagerouter_guid)
--> 201         if 'directory_unlink' in storagerouter.features['volumedriver']['features']:
    202             first = True
    203             devicename_parts = vdisk.devicename.strip('/').split('/')

TypeError: 'NoneType' object has no attribute '__getitem__'

In [9]: 

In [9]: from ovs.dal.hybrids.vdisk import VDisk

In [10]: vdisk = VDisk(vdisk_guid)

In [11]: vdisk
Out[11]: <VDisk (guid: b530ab26-e128-42e6-bf25-c0461b668faa, at: 0x7f8355ee2c50)>

In [12]: print vdisk
2019-05-24 15:14:39 29100 +0800 - Node-42 - 5091/140202688362304 - hybrids/vdisk.py - fetch_statistics - 1 - ERROR - Error loading statistics_volume from bc23f688-b583-40cd-be4f-312647c3a211: Throw location unknown (consider using BOOST_THROW_EXCEPTION)
Dynamic exception type: volumedriverfs::ObjectNotRegisteredException
std::exception::what: std::exception
[volumedriverfs::tag_volume_id*] = bc23f688-b583-40cd-be4f-312647c3a211
 
{
    "edge_clients": [], 
    "cache_quota": null, 
    "has_manual_dtl": false, 
    "guid": "b530ab26-e128-42e6-bf25-c0461b668faa", 
    "size": 2147483648, 
    "devicename": "/\u9a6c.raw", 
    "statistics": {
        "operations": 0, 
        "backend_write_latency": 0, 
        "4k_unaligned_read_operations": 0, 
        "write_latency_distribution": {

........

    "cinder_id": null, 
    "description": "\u9a6c", 
    "vpool_guid": "34f7e980-0d6a-450d-b7cd-c93e4d0a1a39", 
    "storagedriver_id": null, 
    "snapshots": [], 
    "volume_id": "bc23f688-b583-40cd-be4f-312647c3a211", 
    "info": {
        "owner_tag": "<class 'volumedriver.storagerouter.storagerouterclient.OwnerTag'>: OwnerTag(0)", 
        "vrouter_id": "", 
        "object_type": "FILE", 
        "live_status": "RUNNING", 
        "failover_mode": "", 
        "stored": 0, 
        "failover_port": 0, 
        "namespace": "", 
        "volume_size": 0, 
        "cluster_cache_handle": "<class 'volumedriver.storagerouter.storagerouterclient.ClusterCacheHandle'>: ClusterCacheHandle(0)", 
        "parent_volume_id": "", 
        "failover_ip": "", 
        "metadata_backend_config": {}, 
        "parent_namespace": "", 
        "halted": false, 
        "cluster_multiplier": 0, 
        "volume_id": "", 
        "footprint": 0, 
        "lba_count": 0, 
        "lba_size": 0, 
        "parent_snapshot_id": "", 
        "cluster_cache_limit": null, 
        "sco_multiplier": 0
    }, 
    "name": "\u9a6c", 
    "storagerouter_guid": null, 
    "dtl_status": "unknown"
}

[JeffreyDevloo]

Hi Yongshenga

I indeed made some mistakes while writing the small test out.
The version you should use is:

from ovs.dal.lists.vdisklist import VDiskList
from ovs.dal.lists.vpoollist import VPoolList
devicename = "<INSERT NAME HERE>"
vpool_name = "<INSERT VPOOL NAME HERE>"
vpool = VPoolList.get_vpool_by_name(vpool_name)
vdisk = VDiskList.get_by_devicename_and_vpool(devicename, vpool)
if not vdisk:
    # Try an alternative route
    for vd in VDiskList.get_vdisks():
        # Edit: devicename iso device_name
        # Edit2: vd.device_name iso vdisk as vd is the variable of our loop
        if devicename in vd.devicename:
            print 'Found it!'
            vdisk = vd
            break
if not vdisk:
    print 'Found nothing'
else:
    # VDisk is now usable. The framework managed to store it internally
    print vdisk.guid

But it looks like i have the information I need. The VDisk object can be retrieved through a list lookup (for vdisk in VDiskList.get_vdisks()'), but not while performing queries (get_by_devicename_and_vpool`, the unicodewarning is given).
I think the volumedriver is also having issues with the volume too (the object not registered thing). Either you have removed the volume on the volumedriver's end or it's having issues doing a lookup.

The StorageRouter lookup exception puzzles me. I have no clue on what went wrong during that look up. The only thing coming to mind is that an old entry is still cached for that volume and the cluster shrank, but this is an unlikely scenario. If anything it points to #2289 which is also lacking in context.

[yongshengma]

Hi @JeffreyDevloo

I can still access vdisk list from each router's vdisk tab, so it's not a big deal at this moment. I will keep on following this issue. Thanks for your reference.

Best regards
Yongsheng